trace-cmd-report: en línea en la nube

PROGRAMA:

NOMBRE

trace-cmd-report: muestra en ASCII un rastreo creado por el registro trace-cmd

SINOPSIS

seguimiento-cmd (reporte) [OPCIONES] [fichero de entrada]

DESCRIPCIÓN

El seguimiento-cmd(1) el comando de informe generará un informe legible por humanos de un seguimiento creado por
registro trace-cmd.

OPCIONES

-i fichero de entrada
De forma predeterminada, el informe trace-cmd leerá el archivo rastrear.dat. Pero el -i opción abierta
lo dado fichero de entrada en lugar de. Tenga en cuenta que el archivo de entrada también se puede especificar como el último
elemento en la línea de comando.

-e
Esto genera la endiabilidad del archivo. El informe trace-cmd es lo suficientemente inteligente como para poder
leer archivos big endian en máquinas little endian y viceversa.

-f
Esto genera la lista de funciones que se han registrado en el archivo.

-P
Esto genera la lista de datos "trace_printk ()". Los datos de seguimiento sin procesar apuntan a estática
punteros en el kernel. Esto debe almacenarse en el archivo trace.dat.

-E
Esto enumera los posibles eventos en el archivo (pero esta lista no es necesariamente la lista
de eventos en el archivo).

--eventos
Esto mostrará una lista de los formatos de eventos almacenados en el archivo trace.dat.

--evento expresiones regulares
Esto imprimirá eventos que coincidan con la expresión regular dada. Si se especifican dos puntos, entonces el
Los caracteres antes de los dos puntos se utilizarán para hacer coincidir el sistema y los caracteres posteriores.
los dos puntos coincidirán con el evento.

informe de trace-cmd --event sys: read

Lo anterior solo coincidirá con los eventos en los que el nombre del sistema contenga "sys"
y el nombre del evento contiene "leer".

informe trace-cmd - lectura de evento

Lo anterior coincidirá con todos los eventos que contengan "leer" en su nombre. También eso
también puede enumerar todos los eventos de un sistema que contiene "leer".

--check-eventos
Esto analizará las cadenas de formato de eventos que se almacenan en el archivo trace.dat y
devuelve si los formatos se pueden analizar correctamente. Cargará complementos a menos que -N is
especificado.

-t
Imprime la marca de tiempo completa. Las marcas de tiempo en el archivo de datos generalmente se registran en el
nanosegundo. Pero la visualización predeterminada de la marca de tiempo es solo un microsegundo. Para
ver la marca de tiempo completa, agregar el -t .

-F filtrar
Agregue un filtro para limitar los eventos que se muestran. El formato del filtro es:

':'
= SISTEMA '/' EVENTO | SISTEMA | EVENTO | ','
= EVENT_FIELD | '&&' |
'||' | '(' ')' | '!'
= '==' | '! =' | '> =' | '<=' | '>' | '<' | '&' | '|' | '^' |
'+' | '-' | '*' | '/' | '%'
= NUM ​​| STRING | EVENT_FIELD

SISTEMA es el nombre del sistema por el que filtrar. Si el EVENTO se deja fuera,
entonces se aplica a todos los eventos del SISTEMA. Si solo se usa una cuerda
sin la '/' para delimitar entre SISTEMA y EVENTO, entonces el filtro
se aplicará a todos los sistemas y eventos que coincidan con la cadena dada.

Los espacios en blanco se ignoran, de modo que "sched: next_pid == 123" es equivalente a
"sched: next_pid == 123".

STRING se define con comillas simples o dobles (las comillas simples deben terminar con
comillas simples y dobles con doble). Los espacios en blanco entre comillas no son
ignorado

La representación de un SISTEMA o EVENTO también puede ser una expresión regular
Según lo definido por 'compcomp(3) ».

EVENT_FIELD es el nombre del campo de un evento que se está
filtrado. Si el evento no contiene EVENT_FIELD, esa parte del
la ecuación se considerará falsa.

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

El "falso == 1" siempre se evaluará como FALSO porque ningún evento tiene un
campo llamado "falso", pero el "common_pid == 2" seguirá siendo evaluado
ya que todos los eventos tienen el campo "common_pid". Cualquier evento "programado" que fuera
Se mostrará el trazado por el proceso con el PID de 2.

Tenga en cuenta que EVENT_FIELD es el nombre del campo como se muestra en un formato de eventos
(como se muestra con * - eventos *), y no lo que se encuentra en la salida.
Si el resultado muestra "ID: foo" pero el campo al que pertenece "foo" era
llamado "nombre" en el formato de evento, entonces "nombre" debe usarse en el filtro.
Lo mismo ocurre con los valores. Si el valor que se muestra se convierte
mediante un símbolo de cadena, el filtro comprueba el valor original y no el
valor mostrado. Por ejemplo, para filtrar todas las tareas que estaban en el
estado de ejecución en un cambio de contexto:

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

Aunque la salida muestra 'R', tener 'prev_stat == "R"' no funcionará.

Nota: También puede especificar 'COMM' como EVENT_FIELD. Esto usará el
nombre de la tarea (o comunicación) del registro que se va a comparar. Por ejemplo, para filtrar
todas las tareas "trace-cmd":

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

-v
Esto provoca los siguientes filtros de -F para filtrar los eventos coincidentes.

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

No mostrará ningún evento sched_switch que tenga un estado anterior de 0.
Eliminar el * -v * solo imprimirá esos eventos.

-T
Pruebe los filtros de -F. Después de procesar una cadena de filtro, el filtro resultante será
mostrado para cada evento. Esto es útil para usar un filtro para más de un evento.
donde un campo puede no existir en todos los eventos. También se puede utilizar para asegurarse de que haya
ningún nombre de campo de evento mal escrito, ya que simplemente se ignorarán. -T se ignora si -F
no se especifica

-V
Muestra los complementos que están cargados.

-L
Esto no cargará complementos de todo el sistema. Carga "solo local". Eso es lo que encuentra
en la categoría Industrial. ~ / .trace-cmd / complementos directorio.

-N
Esto no cargará ningún complemento.

-n evento-re
Esto hará que todos los eventos que coincidan con la opción ignoren cualquier controlador registrado (por
los complementos) para imprimir el evento. En su lugar, se imprimirá el evento normal. los
evento-re es una expresión regular definida por compcomp(3).

--perfil
Con la --perfil opción, "trace-cmd report" procesará todos los eventos primero, y
luego genera un formato que muestra dónde las tareas han pasado su tiempo en el kernel, también
como dónde están más bloqueados y dónde están las latencias de activación.

See rastrear-cmd-perfil(1) para obtener más detalles y ejemplos.

-H eventos-ganchos
Agregue coincidencia de eventos personalizados para conectar dos eventos.

See rastrear-cmd-perfil(1) para formato.

-R
Esto mostrará los eventos en formato "crudo". Es decir, ignorará la impresión del evento.
formatear y simplemente imprimir el contenido de cada campo.

-r evento-re
Esto hará que todos los eventos que coincidan con la opción impriman sus campos sin procesar. los evento-re
es una expresión regular definida por compcomp(3).

-l
Esto agrega un formato de "salida de latencia". Información sobre interrupciones deshabilitadas, suave
irq está deshabilitado, se establece la bandera "need_resched", cuenta de preferencia y gran kernel
todos los bloqueos se registran con cada evento. Pero la pantalla predeterminada no muestra
esta informacion. Esta opción configurará la visualización de esta información con 6 caracteres.
Cuando uno de los campos es cero o N / A, se muestra un '. \'.

-0 0d.h1. 106467.859747: función: ktime_get <- tick_check_idle

El 0d.h1. denota esta información. El primer carácter nunca es un '.'
y representa en qué CPU se registró el seguimiento (CPU 0). La 'd' denota
que las interrupciones fueron desactivadas. La 'h' significa que esto se llamó dentro
un manejador de interrupciones. El '1' es la preferencia deshabilitada (preempt_count)
se estableció en uno. Los dos '.'s son el indicador "need_resched" y el bloqueo del kernel
encimera. Si se establece la marca "need_resched", ese carácter sería un
'NORTE'.

-w
Si tanto el programar_cambiar y horario_despertar eventos estn habilitados, entonces esta opcin
informar la latencia entre el momento en que la tarea se despertó por primera vez y el momento en que fue
programado en.

-q
Advertencias silenciosas no críticas.

-O
Pase las opciones a los complementos de trace-cmd que están cargados.

-O complemento: var = valor

El 'complemento:' y '= valor' son opcionales. Se puede dejar el valor para las opciones
que son booleanos. Si se deja el 'complemento:', entonces cualquier variable que coincida
en todos los complementos se establecerá.

Ejemplo: -O fgraph: tailprint

--estat
Si el archivo trace.dat registró las estadísticas finales (emitidas al final del registro),
--estat La opción se puede utilizar para recuperarlos.

--tu nombre
Si el archivo trace.dat registró uname durante la ejecución, esto recuperará que

EJEMPLOS

Usando un archivo trace.dat que fue creado con:

# trace-cmd record -p función -e todo duerme 5

El informe predeterminado muestra:

# informe trace-cmd
trace-cmd-16129 [002] 158126.498411: función: __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: función: do_splice_to <- sys_splice
sleep-16133 [001] 158126.498412: función: 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: función: security_file_alloc <- get_empty_filp
sleep-16133 [001] 158126.498422: función: __fsnotify_parent <- vfs_write
trace-cmd-16130 [003] 158126.498422: función: rw_verify_area <- do_splice_to
trace-cmd-16131 [000] 158126.498424: función: cap_file_alloc_security <- security_file_alloc
trace-cmd-16129 [002] 158126.498425: función: syscall_trace_leave <- int_check_syscall_exit_work
sleep-16133 [001] 158126.498426: función: inotify_dentry_parent_queue_event <- vfs_write
trace-cmd-16130 [003] 158126.498426: función: security_file_permission <- rw_verify_area
trace-cmd-16129 [002] 158126.498428: función: audit_syscall_exit <- syscall_trace_leave
[...]

Para ver todo menos las trazas de la función:

# trace-cmd report -v -F 'función'
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 leer all_cpu_access_lock
trace-cmd-16131 [000] 158126.498438: lock_acquire: 0xffff88003df5b520 read & fs-> lock
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)
rastreo-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
dormir-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

Para ver solo las llamadas de kmalloc que tenían más de 1000 bytes:

# 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

Para ver las activaciones y los conmutadores programados que dejaron la tarea anterior en estado de ejecución:

# trace-cmd report -F 'sched: prev_state == 0 || (éxito == 1) '
trace-cmd-16132 [002] 158126.499951: sched_wakeup: comm = trace-cmd pid = 16129 prio = 120 éxito = 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 éxito = 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 éxito = 1 target_cpu = 000
trace-cmd-16131 [002] 158126.506516: sched_wakeup: comm = trace-cmd pid = 16129 prio = 120 éxito = 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 éxito = 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 éxito = 1 target_cpu = 003
trace-cmd-16129 [000] 158126.649287: sched_wakeup: comm = trace-cmd pid = 16131 prio = 120 éxito = 1 target_cpu = 000

Lo anterior necesita una pequeña explicación. El filtro especifica el subsistema "sched", que
incluye los eventos sched_switch y sched_wakeup. Cualquier evento que no tenga la
campo de formato "estado anterior" o "éxito", evaluará esas expresiones como FALSO y
no producir un fósforo. Usando "||" hará que se realice la prueba "prev_state" para el
El evento "sched_switch" y la prueba de "éxito" ocurren para el evento "sched_wakeup".

# trace-cmd report -w -F 'sched_switch, sched_wakeup. *'
[...]
trace-cmd-16130 [003] 158131.580616: sched_wakeup: comm = trace-cmd pid = 16131 prio = 120 éxito = 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 Latencia: 885.901 usecs
trace-cmd-16131 [000] 158131.582414: sched_wakeup: comm = trace-cmd pid = 16129 prio = 120 éxito = 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 Latencia: 804.809 usecs
sleep-16133 [002] 158131.584121: sched_wakeup: comm = trace-cmd pid = 16120 prio = 120 éxito = 1 target_cpu = 002
trace-cmd-16129 [001] 158131.584128: sched_wakeup: comm = trace-cmd pid = 16132 prio = 120 éxito = 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 Latencia: 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 Latencia: 1155.677 usecs

Latencia de activación promedio: 26626.656 usecs

La traza anterior produce las latencias de activación de las tareas. El evento "sched_switch"
informa cada latencia individual después de escribir la información del evento. Al final de
informe, se informa la latencia de activación promedio.

# 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 éxito = 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 Latencia: 101.244 usecs
-0 [003] 158131.533781: sched_wakeup: comm = ksoftirqd / 3 pid = 13 prio = 49 éxito = 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 Latencia: 115.608 usecs
-0 [003] 158131.569730: sched_wakeup: comm = ksoftirqd / 3 pid = 13 prio = 49 éxito = 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 Latencia: 121.024 usecs

Latencia de activación promedio: 110.021 usecs

La versión anterior solo mostrará las activaciones y los cambios de contexto de las tareas en tiempo real. los
prio usado dentro del kernel comienza en 0 para mayor prioridad. Es decir prio 0 es equivalente
al espacio de usuario en tiempo real prioridad 99, y la prioridad 98 es equivalente al espacio de usuario en tiempo real
prioridad 1. Prios inferiores a 100 representan tareas en tiempo real.

Un ejemplo del perfil:

# trace-cmd registro --perfil dormir 1
# informe trace-cmd --profile --comm sleep
tarea: sueño-21611
Evento: sched_switch: R (1) Total: 99442 Promedio: 99442 Máx .: 99442 Mín: 99442
1 total: 99442 mínimo: 99442 máximo: 99442 promedio = 99442
=> ftrace_raw_event_sched_switch (0xffffffff8105f812)
=> __schedule (0xffffffff8150810a)
=> preempt_schedule (0xffffffff8150842e)
=> ___preempt_schedule (0xffffffff81273354)
=> cpu_stop_queue_work (0xffffffff810b03c5)
=> detener_una_cpu (0xffffffff810b063b)
=> sched_exec (0xffffffff8106136d)
=> do_execve_common.isra.27 (0xffffffff81148c89)
=> do_execve (0xffffffff811490b0)
=> SyS_execve (0xffffffff811492c4)
=> return_to_handler (0xffffffff8150e3c8)
=> stub_execve (0xffffffff8150c699)
Evento: sched_switch: S (1) Total: 1000506680 Promedio: 1000506680 Max: 1000506680 Min: 1000506680
1 total: 1000506680 mínimo: 1000506680 máximo: 1000506680 promedio = 1000506680
=> ftrace_raw_event_sched_switch (0xffffffff8105f812)
=> __schedule (0xffffffff8150810a)
=> horario (0xffffffff815084b8)
=> do_nanosleep (0xffffffff8150b22c)
=> hrtimer_nanosleep (0xffffffff8108d647)
=> SyS_nanosleep (0xffffffff8108d72c)
=> return_to_handler (0xffffffff8150e3c8)
=> tracesys_phase2 (0xffffffff8150c304)
Evento: sched_wakeup: 21611 (1) Total: 30326 Promedio: 30326 Max: 30326 Min: 30326
1 total: 30326 mínimo: 30326 máximo: 30326 promedio = 30326
=> ftrace_raw_event_sched_wakeup_template (0xffffffff8105f653)
=> ttwu_do_wakeup (0xffffffff810606eb)
=> ttwu_do_activate.constprop.124 (0xffffffff810607c8)
=> try_to_wake_up (0xffffffff8106340a)

Use trace-cmd-report en línea usando los servicios de onworks.net