Trace-CMD-Report – Online in der Cloud

PROGRAMM:

NAME/FUNKTION

Trace-Cmd-Report – Zeigt in ASCII einen vom Trace-Cmd-Datensatz erstellten Trace an

ZUSAMMENFASSUNG

Trace-Befehl berichten [OPTIONAL] [Eingabedatei]

BESCHREIBUNG

Der Trace-Befehl(1) Der Befehl „report“ gibt einen für Menschen lesbaren Bericht einer von erstellten Ablaufverfolgung aus
Trace-CMD-Datensatz.

OPTIONAL

-i Eingabedatei
Standardmäßig liest der Trace-CMD-Bericht die Datei Trace.dat. Aber der -i Option öffnen
das Gegebene Eingabedatei stattdessen. Beachten Sie, dass die Eingabedatei auch als letzte angegeben werden kann
Element in der Befehlszeile.

-e
Dies gibt die Endianess der Datei aus. Der Trace-CMD-Bericht ist intelligent genug, um dazu in der Lage zu sein
Lesen Sie Big-Endian-Dateien auf Little-Endian-Maschinen und umgekehrt.

-f
Dadurch wird die Liste der Funktionen ausgegeben, die in der Datei aufgezeichnet wurden.

-P
Dies gibt die Liste der „trace_printk()“-Daten aus. Die Rohdaten der Ablaufverfolgung deuten auf statisch hin
Zeiger im Kernel. Dies muss in der Datei „trace.dat“ gespeichert werden.

-E
Dadurch werden die möglichen Ereignisse in der Datei aufgelistet (diese Liste ist jedoch nicht unbedingt die Liste).
der Ereignisse in der Datei).

--Veranstaltungen
Dadurch werden die Ereignisformate aufgelistet, die in der Datei „trace.dat“ gespeichert sind.

--Veranstaltung Regex
Dadurch werden Ereignisse gedruckt, die mit dem angegebenen regulären Ausdruck übereinstimmen. Wenn ein Doppelpunkt angegeben ist, dann wird der
Zeichen vor dem Doppelpunkt werden verwendet, um dem System und den Zeichen danach zu entsprechen
Der Doppelpunkt entspricht dem Ereignis.

Trace-CMD-Bericht --event sys:read

Das Obige gilt nur für Ereignisse, bei denen der Systemname „sys“ enthält.
und der Ereignisname enthält „read“.

Trace-CMD-Bericht --event read

Das Obige stimmt mit allen Ereignissen überein, deren Name „read“ enthält. Auch das
kann alle Ereignisse eines Systems auflisten, das auch „read“ enthält.

--check-events
Dadurch werden die Ereignisformatzeichenfolgen analysiert, die in der Datei „trace.dat“ gespeichert sind
Gibt zurück, ob die Formate korrekt geparst werden können. Es werden Plugins geladen, es sei denn -N is
spezifiziert.

-t
Drucken Sie den vollständigen Zeitstempel aus. Die Zeitstempel in der Datendatei werden normalerweise im aufgezeichnet
Nanosekunde. Die Standardanzeige des Zeitstempels erfolgt jedoch nur auf die Mikrosekunde genau. Zu
Sehen Sie sich den vollständigen Zeitstempel an und fügen Sie den hinzu -t .

-F Filter
Fügen Sie einen Filter hinzu, um die angezeigten Ereignisse einzuschränken. Das Format des Filters ist:

':'
= SYSTEM'/'EVENT | SYSTEM | VERANSTALTUNG | ','
= EVENT_FIELD | '&&' |
'||' | '(' ')' | '!'
= '==' | '!=' | '>=' | '<=' | '>' | '<' | '&' | '|' | '^' |
'+' | '-' | '*' | '/' | '%'
= ANZAHL | STRING | EVENT_FIELD

SYSTEM ist der Name des Systems, nach dem gefiltert werden soll. Wenn das EREIGNIS weggelassen wird,
dann gilt es für alle Ereignisse unter dem SYSTEM. Wenn nur eine Zeichenfolge verwendet wird
ohne das „/“ zur Unterscheidung zwischen SYSTEM und EVENT, dann der Filter
wird auf alle Systeme und Ereignisse angewendet, die der angegebenen Zeichenfolge entsprechen.

Leerzeichen werden ignoriert, sodass „sched:next_pid==123“ äquivalent ist
„sched: next_pid == 123“.

STRING wird mit einfachen oder doppelten Anführungszeichen definiert (einfache Anführungszeichen müssen mit enden).
einfache Anführungszeichen und doppelte mit doppelten Anführungszeichen). Leerzeichen in Anführungszeichen sind nicht vorhanden
ignoriert.

Die Darstellung eines SYSTEMS oder EVENTs kann auch ein regulärer Ausdruck sein
wie definiert durch 'regcomp(3)'.

Das EVENT_FIELD ist der Name des Feldes eines stattfindenden Ereignisses
gefiltert. Wenn das Ereignis das EVENT_FIELD nicht enthält, wird dieser Teil des
Gleichung wird als falsch betrachtet.

-F 'sched : fake == 1 || common_pid == 2'

Das „falsche == 1“ wird immer als FALSCH ausgewertet, da kein Ereignis eine hat
Feld namens „bogus“, aber „common_pid == 2“ wird weiterhin ausgewertet
da alle Ereignisse das Feld „common_pid“ haben. Irgendein „geplantes“ Ereignis
Der vom Prozess mit der PID 2 verfolgte Wert wird angezeigt.

Beachten Sie, dass EVENT_FIELD der Feldname ist, wie er in einem Ereignisformat angezeigt wird
(wie mit *--events* angezeigt) und nicht das, was in der Ausgabe gefunden wird.
Wenn die Ausgabe „ID:foo“ anzeigt, das Feld, zu dem „foo“ gehört, jedoch vorhanden war
Wird im Ereignisformat „Name“ genannt, muss im Filter „Name“ verwendet werden.
Dasselbe gilt auch für Werte. Wenn der angezeigte Wert umgerechnet wird
Durch ein Zeichenfolgensymbol prüft der Filter den ursprünglichen Wert und nicht den
Wert angezeigt. Um beispielsweise nach allen Aufgaben zu filtern, die in der waren
Ausführungsstatus bei einem Kontextwechsel:

-F 'sched/sched_switch: prev_state==0'

Obwohl in der Ausgabe „R“ angezeigt wird, funktioniert „prev_stat=="R"“ nicht.

Hinweis: Sie können „COMM“ auch als EVENT_FIELD angeben. Dies wird die verwenden
Aufgabenname (oder Kommunikation) des zu vergleichenden Datensatzes. Zum Beispiel zum Herausfiltern
alle „trace-cmd“-Aufgaben:

-F '.*:COMM != "trace-cmd"'

-v
Dies führt zu den folgenden Filtern von -F um die passenden Ereignisse herauszufiltern.

-v -F 'sched/sched_switch: prev_state == 0'

Zeigt keine sched_switch-Ereignisse an, die einen prev_state von 0 haben.
Durch das Entfernen von *-v* werden nur diese Ereignisse ausgedruckt.

-T
Testen Sie die Filter von -F. Nach der Verarbeitung einer Filterzeichenfolge wird der resultierende Filter angezeigt
für jedes Ereignis angezeigt. Dies ist nützlich, wenn Sie einen Filter für mehr als ein Ereignis verwenden möchten
wobei ein Feld möglicherweise nicht in allen Fällen vorhanden ist. Es kann auch verwendet werden, um sicherzustellen, dass es welche gibt
Keine falsch geschriebenen Ereignisfeldnamen, da diese einfach ignoriert werden. -T wird ignoriert, wenn -F
ist nicht angegeben.

-V
Zeigt die geladenen Plugins an.

-L
Dadurch werden keine systemweiten Plugins geladen. Es lädt „nur lokal“. Das ist es, was es findet
in England, ~/.trace-cmd/plugins Verzeichnis.

-N
Dadurch werden keine Plugins geladen.

-n Event-Re
Dies führt dazu, dass alle Ereignisse, die mit der Option übereinstimmen, alle registrierten Handler ignorieren (von
die Plugins), um das Ereignis auszudrucken. Stattdessen wird das normale Ereignis gedruckt. Der
Event-Re ist ein regulärer Ausdruck im Sinne von regcomp(3).

--Profil
Mit der --Profil Option „trace-cmd report“ verarbeitet zuerst alle Ereignisse und
Geben Sie dann auch ein Format aus, das zeigt, wo Aufgaben ihre Zeit im Kernel verbracht haben
B. wo sie am meisten blockiert werden und wo es zu Aufwecklatenzen kommt.

Weitere Informationen finden Sie auch in den Trace-CMD-Profil(1) für weitere Details und Beispiele.

-H Event-Hooks
Fügen Sie einen benutzerdefinierten Ereignisabgleich hinzu, um zwei beliebige Ereignisse miteinander zu verbinden.

Weitere Informationen finden Sie auch in den Trace-CMD-Profil(1) für Format.

-R
Dadurch werden die Ereignisse im „Rohformat“ angezeigt. Das heißt, der Ausdruck des Ereignisses wird ignoriert
Formatierung und drucken Sie einfach den Inhalt jedes Felds aus.

-r Event-Re
Dies führt dazu, dass alle Ereignisse, die mit der Option übereinstimmen, ihre Rohfelder drucken. Der Event-Re
ist ein regulärer Ausdruck im Sinne von regcomp(3).

-l
Dadurch wird ein „Latenzausgabe“-Format hinzugefügt. Informationen zu deaktivierten Interrupts, weich
IRQ ist deaktiviert, das „need_resched“-Flag ist gesetzt, Preempt-Anzahl und großer Kernel
Sperre werden alle bei jedem Ereignis aufgezeichnet. Die Standardanzeige wird jedoch nicht angezeigt
diese Information. Mit dieser Option wird die Anzeige dieser Informationen mit 6 Zeichen eingestellt.
Wenn eines der Felder Null oder N/A ist, wird ein „.\“ angezeigt.

-0 0d.h1. 106467.859747: Funktion: ktime_get <-- tick_check_idle

Das 0d.h1. bezeichnet diese Information. Das erste Zeichen ist niemals ein „.“
und stellt dar, auf welcher CPU der Trace aufgezeichnet wurde (CPU 0). Das 'd' bezeichnet
dass Interrupts deaktiviert waren. Das „h“ bedeutet, dass dies im Inneren aufgerufen wurde
ein Interrupt-Handler. Die „1“ ist die deaktivierte Vorkaufsberechtigung (preempt_count).
wurde auf eins gesetzt. Die beiden '.'s sind das Flag "need_resched" und die Kernel-Sperre
Schalter. Wenn das Flag „need_resched“ gesetzt ist, wäre dieses Zeichen ein
'N'.

-w
Wenn beide sched_switch und sched_wakeup Wenn Ereignisse aktiviert sind, ist diese Option aktiviert
Melden Sie die Latenz zwischen dem Zeitpunkt, zu dem die Aufgabe zum ersten Mal aktiviert wurde, und dem Zeitpunkt, zu dem sie aktiviert wurde
eingeplant.

-q
Leise, nicht kritische Warnungen.

-O
Übergeben Sie Optionen an die geladenen Trace-CMD-Plugins.

-O Plugin:var=Wert

„Plugin:“ und „=Wert“ sind optional. Bei Optionen kann der Wert weggelassen werden
das sind boolesche Werte. Wenn „plugin:“ weggelassen wird, dann jede Variable, die übereinstimmt
in allen Plugins wird gesetzt.

Beispiel: -O fgraph:tailprint

-stat
Wenn in der Datei „trace.dat“ die endgültigen Statistiken aufgezeichnet wurden (am Ende der Aufzeichnung ausgegeben), werden die
-stat Mit der Option können sie abgerufen werden.

--dein Name
Wenn die Datei „trace.dat“ während des Laufs „uname“ aufgezeichnet hat, wird dies abgerufen
Informationen.

Beispiele:

Verwenden einer Trace.dat-Datei, die erstellt wurde mit:

# Trace-CMD Record -p Funktion -e All Sleep 5

Der Standardbericht zeigt:

# Trace-CMD-Bericht
Trace-cmd-16129 [002] 158126.498411: Funktion: __mutex_unlock_slowpath <-- mutex_unlock
Trace-cmd-16131 [000] 158126.498411: kmem_cache_alloc: call_site=811223c5 ptr=0xffff88003ecf2b40 bytes_req=272 bytes_alloc=320 gfp_flags=GFP_KERNEL|GFP_ZERO
Trace-cmd-16130 [003] 158126.498411: Funktion: do_splice_to <-- sys_splice
sleep-16133 [001] 158126.498412: Funktion: inotify_inode_queue_event <-- vfs_write
Trace-cmd-16129 [002] 158126.498420: lock_release: 0xffff88003f1fa4f8 &sb->s_type->i_mutex_key
Trace-cmd-16131 [000] 158126.498421: Funktion: security_file_alloc <-- get_empty_filp
sleep-16133 [001] 158126.498422: Funktion: __fsnotify_parent <-- vfs_write
Trace-cmd-16130 [003] 158126.498422: Funktion: rw_verify_area <-- do_splice_to
Trace-cmd-16131 [000] 158126.498424: Funktion: cap_file_alloc_security <-- security_file_alloc
Trace-cmd-16129 [002] 158126.498425: Funktion: syscall_trace_leave <-- int_check_syscall_exit_work
sleep-16133 [001] 158126.498426: Funktion: inotify_dentry_parent_queue_event <-- vfs_write
Trace-cmd-16130 [003] 158126.498426: Funktion: security_file_permission <-- rw_verify_area
Trace-cmd-16129 [002] 158126.498428: Funktion: audit_syscall_exit <-- syscall_trace_leave
[...]

Um alles außer den Funktionsspuren anzuzeigen:

# Trace-CMD-Bericht -v -F 'Funktion'
Trace-cmd-16131 [000] 158126.498411: kmem_cache_alloc: call_site=811223c5 ptr=0xffff88003ecf2b40 bytes_req=272 bytes_alloc=320 gfp_flags=GFP_KERNEL|GFP_ZERO
Trace-cmd-16129 [002] 158126.498420: lock_release: 0xffff88003f1fa4f8 &sb->s_type->i_mutex_key
Trace-cmd-16130 [003] 158126.498436: lock_acquire: 0xffffffff8166bf78 all_cpu_access_lock lesen
Trace-cmd-16131 [000] 158126.498438: lock_acquire: 0xffff88003df5b520 &fs->lock lesen
Trace-cmd-16129 [002] 158126.498446: kfree: call_site=810a7abb ptr=0x0
Trace-cmd-16130 [003] 158126.498448: lock_acquire: 0xffff880002250a80 &per_cpu(cpu_access_lock, cpu)
Trace-cmd-16129 [002] 158126.498450: sys_exit_splice: 0xfffffff5
Trace-cmd-16131 [000] 158126.498454: lock_release: 0xffff88003df5b520 &fs->lock
sleep-16133 [001] 158126.498456: kfree: call_site=810a7abb ptr=0x0
sleep-16133 [001] 158126.498460: sys_exit_write: 0x1
Trace-cmd-16130 [003] 158126.498462: kmalloc: call_site=810bf95b ptr=0xffff88003dedc040 bytes_req=24 bytes_alloc=32 gfp_flags=GFP_KERNEL|GFP_ZERO

Um nur die kmalloc-Aufrufe anzuzeigen, die größer als 1000 Byte waren:

#trace-cmd report -F 'kmalloc: bytes_req > 1000'
-0 [000] 158128.126641: kmalloc: call_site=81330635 ptr=0xffff88003c2fd000 bytes_req=2096 bytes_alloc=4096 gfp_flags=GFP_ATOMIC

So sehen Sie Weckvorgänge und Zeitplanwechsel, die die vorherige Aufgabe im laufenden Zustand belassen haben:

# Trace-cmd Report -F 'sched: prev_state == 0 || (Erfolg == 1)'
Trace-cmd-16132 [002] 158126.499951: sched_wakeup: comm=trace-cmd pid=16129 prio=120 success=1 target_cpu=002
Trace-cmd-16132 [002] 158126.500401: sched_switch: prev_comm=trace-cmd prev_pid=16132 prev_prio=120 prev_state=R ==> next_comm=trace-cmd next_pid=16129 next_prio=120
-0 [003] 158126.500585: sched_wakeup: comm=trace-cmd pid=16130 prio=120 success=1 target_cpu=003
-0 [003] 158126.501241: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=trace-cmd next_pid=16130 next_prio=120
Trace-cmd-16132 [000] 158126.502475: sched_wakeup: comm=trace-cmd pid=16131 prio=120 success=1 target_cpu=000
Trace-cmd-16131 [002] 158126.506516: sched_wakeup: comm=trace-cmd pid=16129 prio=120 success=1 target_cpu=002
-0 [003] 158126.550110: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=trace-cmd next_pid=16130 next_prio=120
Trace-cmd-16131 [003] 158126.570243: sched_wakeup: comm=trace-cmd pid=16129 prio=120 success=1 target_cpu=003
Trace-cmd-16130 [002] 158126.618202: sched_switch: prev_comm=trace-cmd prev_pid=16130 prev_prio=120 prev_state=R ==> next_comm=yum-updatesd next_pid=3088 next_prio=1 20
Trace-cmd-16129 [003] 158126.622379: sched_wakeup: comm=trace-cmd pid=16131 prio=120 success=1 target_cpu=003
Trace-cmd-16129 [000] 158126.649287: sched_wakeup: comm=trace-cmd pid=16131 prio=120 success=1 target_cpu=000

Das Obige bedarf einer kleinen Erklärung. Der Filter gibt das „sched“-Subsystem an, das
Enthält sowohl sched_switch- als auch sched_wakeup-Ereignisse. Jede Veranstaltung, bei der das nicht der Fall ist
Formatfeld „prev_state“ oder „success“, wertet diese Ausdrücke als FALSE aus und wird dies auch tun
keine Übereinstimmung erzeugen. Verwendung von „||“ wird der „prev_state“-Test für durchgeführt
Das Ereignis „sched_switch“ und der „success“-Test finden für das Ereignis „sched_wakeup“ statt.

# Trace-cmd Report -w -F 'sched_switch, sched_wakeup.*'
[...]
Trace-cmd-16130 [003] 158131.580616: sched_wakeup: comm=trace-cmd pid=16131 prio=120 success=1 target_cpu=003
Trace-cmd-16129 [000] 158131.581502: sched_switch: prev_comm=trace-cmd prev_pid=16129 prev_prio=120 prev_state=S ==> next_comm=trace-cmd next_pid=16131 next_prio=120 Latenz: 885.901 usecs
Trace-cmd-16131 [000] 158131.582414: sched_wakeup: comm=trace-cmd pid=16129 prio=120 success=1 target_cpu=000
Trace-cmd-16132 [001] 158131.583219: sched_switch: prev_comm=trace-cmd prev_pid=16132 prev_prio=120 prev_state=S ==> next_comm=trace-cmd next_pid=16129 next_prio=120 Latenz: 804.809 usecs
sleep-16133 [002] 158131.584121: sched_wakeup: comm=trace-cmd pid=16120 prio=120 success=1 target_cpu=002
Trace-cmd-16129 [001] 158131.584128: sched_wakeup: comm=trace-cmd pid=16132 prio=120 success=1 target_cpu=001
sleep-16133 [002] 158131.584275: sched_switch: prev_comm=sleep prev_pid=16133 prev_prio=120 prev_state=R ==> next_comm=trace-cmd next_pid=16120 next_prio=120 Latenz: 153.915 usecs
Trace-cmd-16130 [003] 158131.585284: sched_switch: prev_comm=trace-cmd prev_pid=16130 prev_prio=120 prev_state=S ==> next_comm=trace-cmd next_pid=16132 next_prio=120 Latenz: 1155.677 usecs

Durchschnittliche Aktivierungslatenz: 26626.656 Sekunden

Der obige Trace erzeugt die Aktivierungslatenzen der Aufgaben. Das „sched_switch“-Ereignis
meldet jede einzelne Latenz nach dem Schreiben der Ereignisinformationen. Am Ende von
Im Bericht wird die durchschnittliche Aktivierungslatenz angegeben.

# trace-cmd report -w -F 'sched_switch, sched_wakeup.*: prio < 100 || next_prio < 100'
-0 [003] 158131.516753: sched_wakeup: comm=ksoftirqd/3 pid=13 prio=49 success=1 target_cpu=003
-0 [003] 158131.516855: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=ksoftirqd/3 next_pid=13 next_prio=49 Latenz: 101.244 Sekunden
-0 [003] 158131.533781: sched_wakeup: comm=ksoftirqd/3 pid=13 prio=49 success=1 target_cpu=003
-0 [003] 158131.533897: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=ksoftirqd/3 next_pid=13 next_prio=49 Latenz: 115.608 Sekunden
-0 [003] 158131.569730: sched_wakeup: comm=ksoftirqd/3 pid=13 prio=49 success=1 target_cpu=003
-0 [003] 158131.569851: sched_switch: prev_comm=swapper prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=ksoftirqd/3 next_pid=13 next_prio=49 Latenz: 121.024 Sekunden

Durchschnittliche Aktivierungslatenz: 110.021 Sekunden

Die obige Version zeigt nur die Weckvorgänge und Kontextwechsel von Echtzeitaufgaben an. Der
prio Wird im Kernel verwendet und beginnt bei 0 für die höchste Priorität. Das ist prio 0 ist gleichwertig
Die Echtzeitpriorität 99 des Benutzerbereichs entspricht der Echtzeitpriorität 98 des Benutzerbereichs
Priorität 1. Prios unter 100 stehen für Echtzeitaufgaben.

Ein Beispiel für das Profil:

# Trace-cmd Record --profile Sleep 1
# Trace-cmd Report --profile --comm Sleep
Aufgabe: Schlaf-21611
Ereignis: sched_switch:R (1) Gesamt: 99442 Durchschnitt: 99442 Maximal: 99442 Min: 99442
1 gesamt:99442 min:99442 max:99442 avg=99442
=> ftrace_raw_event_sched_switch (0xffffffff8105f812)
=> __schedule (0xffffffff8150810a)
=> preempt_schedule (0xffffffff8150842e)
=> ___preempt_schedule (0xffffffff81273354)
=> cpu_stop_queue_work (0xffffffff810b03c5)
=> stop_one_cpu (0xffffffff810b063b)
=> sched_exec (0xffffffff8106136d)
=> do_execve_common.isra.27 (0xffffffff81148c89)
=> do_execve (0xffffffff811490b0)
=> SyS_execve (0xffffffff811492c4)
=> return_to_handler (0xffffffff8150e3c8)
=> stub_execve (0xffffffff8150c699)
Ereignis: sched_switch:S (1) Gesamt: 1000506680 Durchschnitt: 1000506680 Max: 1000506680 Min: 1000506680
1 gesamt:1000506680 min:1000506680 max:1000506680 avg=1000506680
=> ftrace_raw_event_sched_switch (0xffffffff8105f812)
=> __schedule (0xffffffff8150810a)
=> Zeitplan (0xffffffff815084b8)
=> do_nanosleep (0xffffffff8150b22c)
=> hrtimer_nanosleep (0xffffffff8108d647)
=> SyS_nanosleep (0xffffffff8108d72c)
=> return_to_handler (0xffffffff8150e3c8)
=> Tracesys_phase2 (0xffffffff8150c304)
Ereignis: sched_wakeup:21611 (1) Gesamt: 30326 Durchschnitt: 30326 Max: 30326 Min: 30326
1 gesamt:30326 min:30326 max:30326 avg=30326
=> ftrace_raw_event_sched_wakeup_template (0xffffffff8105f653)
=> ttwu_do_wakeup (0xffffffff810606eb)
=> ttwu_do_activate.constprop.124 (0xffffffff810607c8)
=> try_to_wake_up (0xffffffff8106340a)

Verwenden Sie den Trace-CMD-Report online über die Dienste von onworks.net