genode/repos/os/recipes/pkg/test-trace_logger/runtime
Norman Feske 3394f97f86 trace_logger: make output format more concise
This patch changes the output format of the trace logger to become
better suitable for human consumption. For example, when instrumenting
the VFS server in Sculpt using the GENODE_TRACE_TSC utility, the
trace logger now generates tabular output as follows.

  Report 4

  PD "init -> runtime -> arch_vbox6 -> vbox -> " ----------------
   Thread "vCPU"           at (0,0)  total:12909024 recent:989229
   Thread "vCPU"           at (1,0)  total:5643234  recent:786437

  PD "init -> runtime -> ahci-0.fs" -----------------------------
   Thread "ahci-0.fs"      at (0,0)  total:910497   recent:6335
   Thread "ep"             at (0,0)  total:0        recent:0
    71919692932: TSC process_packets: 8005M (4998 calls, last 4932K)
    71921558516: TSC process_packets: 8006M (4999 calls, last 1596K)
    71922760220: TSC process_packets: 8007M (5000 calls, last 1006K)
    71929853586: TSC process_packets: 8009M (5001 calls, last 1840K)
    71931315246: TSC process_packets: 8011M (5002 calls, last 1253K)
    72127999920: TSC process_packets: 8016M (5003 calls, last 5606K)
    72129568198: TSC process_packets: 8018M (5004 calls, last 1345K)
    77161908178: TSC process_packets: 8029M (5005 calls, last 11349K)
    77643225736: TSC process_packets: 8029M (5006 calls, last 217K)
    89422100594: TSC process_packets: 8035M (5007 calls, last 5656K)
    89422123632: TSC process_packets: 8035M (5008 calls, last 1342)
   Thread "signal handler" at (0,0)  total:36329    recent:3001
   Thread "signal_proxy"   at (0,0)  total:51838    recent:13099
   Thread "pdaemon"        at (0,0)  total:97184    recent:332
   Thread "vdrain"         at (0,0)  total:1266     recent:286
   Thread "vrele"          at (0,0)  total:1904     recent:516

  PD "init -> runtime -> nic_drv" -------------------------------
   Thread "nic_drv"        at (0,0)  total:34044    recent:897
   Thread "signal handler" at (0,0)  total:369      recent:142

  ...

Subjects that belong to the same PD are grouped together. The formerly
optional affinity and activity options have been removed. Those
information are now unconditionally displayed. The trace entries
belonging to a thread appear as slightly indented.

The patch also updates the coding style, avoiding excessively long
lines.

Issue #4448
2022-04-13 08:07:58 +02:00

127 lines
3.5 KiB
Plaintext

<runtime ram="100M" caps="1000" binary="init">
<requires> <timer/> </requires>
<events>
<timeout meaning="failed" sec="20" />
<log meaning="succeeded">
[init -> trace_logger] Report *
[init -> trace_logger] PD "init -> dynamic -> test-trace_logger -> cpu_burner.*"*
[init -> trace_logger] Thread "ep" at (0,0) TRACED total:* recent:*
[init -> trace_logger] PD "init -> dynamic -> test-trace_logger -> dynamic_rom"*
[init -> trace_logger] Thread "ep" at (0,0) TRACED total:* recent:*
[init -> trace_logger] PD "init -> dynamic -> test-trace_logger -> test-trace_logger"*
[init -> trace_logger] Thread "ep" at (0,0) TRACED total:* recent:*
[init -> trace_logger] 100 *
[init -> trace_logger] trigger_once
[init -> trace_logger] trigger_once
</log>
</events>
<content>
<rom label="ld.lib.so"/>
<rom label="dynamic_rom"/>
<rom label="cpu_burner"/>
<rom label="test-trace_logger"/>
<rom label="trace_logger"/>
<rom label="null"/>
<rom label="rpc_name"/>
<rom label="log_output"/>
</content>
<config>
<parent-provides>
<service name="ROM"/>
<service name="IRQ"/>
<service name="IO_MEM"/>
<service name="IO_PORT"/>
<service name="PD"/>
<service name="RM"/>
<service name="CPU"/>
<service name="LOG"/>
<service name="TRACE"/>
<service name="Timer"/>
</parent-provides>
<default-route>
<any-service> <parent/> <any-child/> </any-service>
</default-route>
<default caps="100"/>
<start name="trace_logger" >
<resource name="RAM" quantum="80M"/>
<config verbose="yes"
session_ram="10M"
session_parent_levels="1"
session_arg_buffer="64K"
period_sec="3"
default_policy="null"
default_buffer="1K">
<policy label_prefix="init -> dynamic -> test-trace_logger -> cpu_burner"
thread="ep"/>
<policy label="init -> dynamic -> test-trace_logger -> test-trace_logger"
thread="ep"
buffer="4K"
policy="rpc_name"/>
<policy label="init -> dynamic -> test-trace_logger -> dynamic_rom"
thread="ep"
buffer="8K"
policy="log_output"/>
</config>
</start>
<start name="dynamic_rom">
<resource name="RAM" quantum="4M"/>
<provides><service name="ROM"/></provides>
<config verbose="yes">
<rom name="cpu_burner1.config">
<inline description="initial state">
<config percent="5"/>
</inline>
<sleep milliseconds="5000" />
<inline description="50%">
<config percent="50" />
</inline>
<sleep milliseconds="5000" />
</rom>
<rom name="cpu_burner2.config">
<inline description="initial state">
<config percent="5"/>
</inline>
<sleep milliseconds="4800" />
<inline description="100%">
<config percent="70" />
</inline>
<sleep milliseconds="2700" />
</rom>
</config>
</start>
<start name="test-trace_logger" >
<resource name="RAM" quantum="1M"/>
</start>
<start name="cpu_burner.1">
<binary name="cpu_burner"/>
<resource name="RAM" quantum="1M"/>
<route>
<service name="ROM" label="config">
<child name="dynamic_rom" label="cpu_burner1.config"/> </service>
<any-service> <parent/> <any-child/> </any-service>
</route>
</start>
<start name="cpu_burner.2">
<binary name="cpu_burner"/>
<resource name="RAM" quantum="1M"/>
<route>
<service name="ROM" label="config">
<child name="dynamic_rom" label="cpu_burner2.config"/> </service>
<any-service> <parent/> <any-child/> </any-service>
</route>
</start>
</config>
</runtime>