A set of utilities to logs with time data in it and convert to trace event file format for a certain ADMS client timing log files and apache httpd access logs.

A very nice viewer for the trace event file can be found here https://ui.perfetto.dev/

Format for the time event file can be found here https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview

The scipt can be found in cronos/convert_time_log.py it shouldn't have dependencies outside the standard python libraries.

Examples of use,

This will generate a trace event file with the name logs/ADMSClientTiming_07_12_2021.json

python cronos/convert_time_log.py -f logs/ADMSClientTiming_07_12_2021.log

To name the output file,

python cronos/convert_time_log.py -f logs/ADMSClientTiming_07_12_2021.log -o example.json

And to output to stdout

python cronos/convert_time_log.py -f logs/ADMSClientTiming_07_12_2021.log -s 

For apache httpd logs

python cronos/convert_time_log.py -a logs/access.log.2021-12-03 -o access.log.2021-12-03.json

Then open and load the generated json file into the viewer at https://ui.perfetto.dev/

When traces are loaded into the perfetto viewer, you can use the Query(SQL) tool to filter on the trace data.

There seems to be two main tables created at loaded, slice and args, there may be more but have not looked at them.

slice holds the event data and args holds all the parameters, joint on them using arg_set_id

Note dur is in nano seconds, divide by 10^9 to get seconds.

All events matching a specific name,

select name, dur/1000000000.0,cat,a.string_value as event_time from slice s,args a where s.arg_set_id = a.arg_set_id  and
name like '/enmac/alarmevent%'
and a.flat_key = 'args.start';

finding the max or min of a specific event name.

select max(dur)/1000000000.0,min(dur)/1000000000.0 from slice where name like '/enmac/alarmevent%';

Select the thing that takes the longest time

select name,dur/1000000000.0,cat,string_value as event_time from slice s,args a 
where dur in (select  max(dur) from slice) and 
s.arg_set_id = a.arg_set_id and 
flat_key ='args.start';

select all events where serverCPU is greater than 0.05seconds

select distinct name,dur/1000000000.0 as 'duration(s)',category,real_value as serverCPU from 
slice s,args a 
where 
s.arg_set_id = a.arg_set_id and
key = 'args.serverCPU' and real_value > 0.05;

Enable this feature in the Support section on the LHS under flags

results in a pivot table with the following columns

The script has been developed with nbdev as the markup/test env. See https://nbdev.fast.ai/tutorial.html for more information.

Contributions are welcome.

Copyright 2021-present Bill Traill 3ideas.co.uk. Released under the terms of the MIT license.

If you're using the library in a commercial enviroment or product, please consider sponsoring its development or paying for maintenace of it. Contact bill@3ideas.co.uk