Re: Bash Einzeiler Zeit+Datum letzter Eintrag dmesg
Am Samstag, 20. August 2011 schrieb David Haller:
> Hallo,
>
> Am Mon, 15 Aug 2011, Rico Koerner schrieb:
> >Am 15.08.2011 08:39, schrieb David Haller:
> >> Am Sun, 14 Aug 2011, Rico Koerner schrieb:
> >>> David hat mich durch den Hinweis auf syslog bei der Fehlersuche
> >>> jetzt noch auf einen anderen Lösungsweg gebracht. Da die Zeile aus
> >>> dmesg auch in einer Zeile im Syslog auftaucht, braucht man doch
> >>> gar nicht anfangen zu rechnen sondern einfach nur die passende
> >>> Zeile aus dem syslog ziehen.
> >>
> >> Haaalt! Konkretes Beispiel: bei mir schreibt syslog-ng z.B. firewall
> >> und /dev/sr0 betreffende Einträge in jew. eigene Logs (die würden
> >> mir sonst das eigentliche nur zumüllen). Ergo müßte ich man in
> >> mehreren Dateien rumgreppen ... Der letzte Eintrag in dmesg findet
> >> sich bei mir grad nur(!) in /v/l/firewall.
> >
> >Ja, jeder Ansatz hat seine eigenen Vor- und Nachteile.
> >Auch die Vorgabe "ohne root" war mir nicht bewußt. Wem die Gruppe adm
> >noch zu großzügig ist, kann es ja auch mit ACLs auf syslog versuchen.
> >Wenn die Logs abweichend sind, scheitert mein Ansatz natürlich auch,
> >u.U. müssten dann mehrere Logs durchsucht werden.
> >Dafür ist das Ergebnis genauer, weil die Abweichung zwischen den
> >Zählern nicht verfälschen.
> >
> >> dmesg ist also schon der richtige Ansatz.
> >
> >Das hab ich ja nicht verworfen.
> >
> >>> Dort steht die Zeit ja schon am Anfang der Zeile. Somit wird immer
> >>> die korrekte Zeit ausgegeben.
> >
> >Nein, eben nicht. Die Abweichung wurde ja nun schon mehrfach
> >festgestellt. Nur deshalb hab ich den Weg verfolgt.
>
> Wie gesagt, ich denke das ist ein Sonderfall. Leider hat Frank keine
> "Rohdaten" (uptime, timestamp in dmesg/syslog) mit denen dann
> weitergerechnet wird geliefert.
>
> [..]
>
> >> Und die andere Variante, die ebenfalls /proc/uptime ausliest dürfte
> >> noch lahmer sein.
> >
> >Lassen wir mal die Vermutungen beiseite und führen das aus.
> >Mein Rechner ist allerdings insgesamt nicht so schnell,
>
> Och, meiner auch nicht, war zum Kaufzeitpunkt vor ~1.5 Jahren schon
> eine der langsamsten CPUs (Athlon II X2 250 (2x3.0 GHz)). Mir war
> Single-Core Leistung eben wichtiger als 4 Kerne[0] ;)
>
> >Die Ausgangsvariante:
> >~# time { for i in {1..1000}; do let lastentry=$(dmesg|tail -n 1|cut
> >-f1 -d"."|cut -c2-|cut -f2 -d" "); let boot=$(cut -f1 -d.
> >/proc/uptime); let lastdate=$boot-$lastentry; date -d "$lastdate
> >seconds ago"; done > /dev/null; }
> >
> >real 0m17.204s
> >user 0m5.704s
> >sys 0m16.753s
> >
> >AWK:
> >~# time { for i in {1..1000}; do date -d "$(dmesg | gawk -F'[][ ]+'
> >'BEGIN{getline<"/proc/uptime";u=$1;} END{printf("%i\n",u-$2);}')
> >seconds ago"; done > /dev/null; }
> >
> >real 0m13.924s
> >user 0m5.468s
> >sys 0m9.261s
>
> *hehe*
>
> >Syslog:
> >~# time { for i in {1..1000}; do LASTENTRY=`dmesg | tail -n1`;
> >LASTTIME=${LASTENTRY%%]*}; grep ${LASTTIME#[} /var/log/syslog | cut
> >-c-15; done > /dev/null; }
> >
> >real 0m15.713s
> >user 0m5.204s
> >sys 0m11.057s
>
> Wobei man hier ergänzen sollte: 'cut -c' oder andere zeichenabhängiger
> Kram sind immer "fragil". Musterbasierte wie cut -fN -dX, die awk-
> oder sed-Variante sind robuster.
>
> >Bash only:
> >~# time { for i in {1..1000}; do LASTENTRY=`dmesg | tail -n1`;
> >LASTTIME=${LASTENTRY%%.*}; BOOT=`cat /proc/uptime`; date -d
> >"$((${BOOT%%.*} - ${LASTTIME#[})) seconds ago"; done > /dev/null; }
> >
> >real 0m15.433s
> >user 0m4.112s
> >sys 0m11.569s
> >
> >Ja, awk ist hier am schnellsten.
> >Erstaunlicherweise ist grep+cut nicht wesentlich schlechter als
> >cat+date. Suchen wir doch mal den Zeitfresser.
>
> Wie gesagt: Prozesse starten ist "teuer". Das schlägt hier wohl durch.
>
> >Ich klammer mal die einzelnen Aufrufe aus der Schleife aus:
> >~# time { LASTENTRY=`dmesg | tail -n1`; for i in {1..1000}; do
> >LASTTIME=${LASTENTRY%%.*}; BOOT=`cat /proc/uptime`; date -d
> >"$((${BOOT%%.*} - ${LASTTIME#[})) seconds ago"; done > /dev/null; }
> >
> >real 0m4.661s
> >user 0m1.264s
> >sys 0m3.132s
> >
> >dmesg|tail schluckt schon mal >10s, also schon mal 2/3 der Gesamtzeit.
> >
> >~# time { for i in {1..1000}; do dmesg; done > /dev/null; }
> >real 0m7.649s
> >user 0m2.636s
> >sys 0m5.152s
> >
> >Den größten Teil davon benötigt dmesg selbst, ist also nicht
> >vermeidbar. Bleiben ca. 3s für tail.
> >
> >~# time { BOOT=`cat /proc/uptime`; for i in {1..1000}; do
> >LASTENTRY=`dmesg | tail -n1`; LASTTIME=${LASTENTRY%%.*}; date -d
> >"$((${BOOT%%.*} - ${LASTTIME#[})) seconds ago"; done > /dev/null; }
> >
> >real 0m12.770s
> >user 0m3.708s
> >sys 0m9.517s
> >
> >cat ist auch mit ca. 3s dabei
> >
> >
> >~# time { for i in {1..1000}; do LASTENTRY=`dmesg | tail -n1`;
> >LASTTIME=${LASTENTRY%%.*}; BOOT=`cat /proc/uptime`; done; date -d
> >"$((${BOOT%%.*} - ${LASTTIME#[})) seconds ago" > /dev/null; }
> >
> >real 0m12.775s
> >user 0m3.960s
> >sys 0m9.365s
> >
> >date ebenfalls.
> >
> >> Mantra: Prozesse starten, Disk- und Console-I/O ist lahm!
> >
> >Dann spar dir doch auch den seq-Aufruf, das kann die bash auch allein.
> >;-)
> >
> >-- for i in `seq 1 1000`;
> >++ for i in {1..1000};
>
> Ach, alte Gewohnheit, hab 10 Jahre mit bash-2.x programmiert ... Und
>
> 1. es ist genau 1 Aufruf pro Durchlauf (und nicht _in_ der Schleife)
>
> 2. Der Unterschied ist gar nicht mal groß (kleinster und größer Wert
> aus 3 Durchläufen):
>
> $ time for i in `seq 1 1000000`; do :; done
> real 0m2.588s
> real 0m2.691s
> $ time for i in {1..1000000}; do :; done
> real 0m2.245s
> real 0m2.273s
Na, auf meinen Sandybridge-Notebook mit geringerer Singlecore-For-
Schleifen-Leistung als Deiner Maschine ist der Unterschied schon größer:
martin@merkaba:~> bash
martin@merkaba:~ -> time for i in `seq 1 1000000`; do :; done
real 0m3.547s
user 0m3.524s
sys 0m0.060s
martin@merkaba:~ -> time for i in `seq 1 1000000`; do :; done
real 0m3.521s
user 0m3.500s
sys 0m0.056s
martin@merkaba:~ -> time for i in `seq 1 1000000`; do :; done
real 0m3.481s
user 0m3.480s
sys 0m0.036s
martin@merkaba:~ -> time for i in {1..1000000}; do :; done
real 0m2.786s
user 0m2.748s
sys 0m0.028s
martin@merkaba:~ -> time for i in {1..1000000}; do :; done
real 0m2.688s
user 0m2.664s
sys 0m0.008s
martin@merkaba:~ -> time for i in {1..1000000}; do :; done
real 0m2.676s
user 0m2.652s
sys 0m0.012s
Interessanterweise schneidet die neumodische Schreibweise deutlich
schlechter ab:
martin@merkaba:~ -> time for (( i=1; i<=1000000; i=i+1 )); do :; done
real 0m6.178s
user 0m6.032s
sys 0m0.128s
martin@merkaba:~ -> time for (( i=1; i<=1000000; i=i+1 )); do :; done
real 0m6.170s
user 0m5.976s
sys 0m0.176s
martin@merkaba:~ -> time for (( i=1; i<=1000000; i=i+1 )); do :; done
real 0m6.182s
user 0m6.012s
sys 0m0.152s
martin@merkaba:~ ->
Dass die bash jedoch sehr ineffizient mit Schleifen umgeht zeigt:
martin@merkaba:~ -> cat count.rb
#!/usr/bin/env ruby
for i in 0..1000000
end
martin@merkaba:~ -> time ./count.rb
real 0m0.082s
user 0m0.056s
sys 0m0.020s
martin@merkaba:~ -> time ./count.rb
real 0m0.069s
user 0m0.048s
sys 0m0.020s
martin@merkaba:~ -> time ./count.rb
real 0m0.076s
user 0m0.056s
sys 0m0.016s
Oder gar:
martin@merkaba:~ -> time ruby ./count.rb
real 0m0.067s
user 0m0.044s
sys 0m0.016s
martin@merkaba:~ -> time ruby ./count.rb
real 0m0.062s
user 0m0.044s
sys 0m0.012s
martin@merkaba:~ -> time ruby ./count.rb
real 0m0.063s
user 0m0.044s
sys 0m0.012s
martin@merkaba:~#127> ruby --version
ruby 1.8.7 (2011-06-30 patchlevel 352) [x86_64-linux]
Ciao,
--
Martin 'Helios' Steigerwald - http://www.Lichtvoll.de
GPG: 03B0 0D6C 0040 0710 4AFA B82F 991B EAAC A599 84C7
Reply to: