Record time of every process or thread context switch

debugginglogsprocessprofilingreal time

I'm trying to get the nearest to real-time processing I can with a Raspbian distribution on a Raspberry Pi for manipulating its GPIO pins. I want to get a "feel" for the kind of performance I can expect.

I was going to do this by writing a simple C program that toggles a pin repeatedly as fast as possible, and monitoring it with a logic analyser.

But perhaps there's another way, by writing the above program but simply logging context switches to see exactly when that thread/process has control over a sample period of say a couple of seconds.

This previous question answers how to see how many context switches are made in some period of time for a given process, but is there a way of logging the precise timing of switches, and perhaps for every process, not just one? Obviously this would create overhead, but could still be useful. Obviously the data should be stored in RAM to minimise overhead

Note to self: possible solutions:

  • Command to list in real time all the actions of a process
  • Hacky: make the program repeatedly get and store the current time (and save it to a file once the log reaches a certain limit). Or, a slight improvement to avoid enormous logs: use an algorithm that eliminates consecutive times if they are close enough together that it can be deduced they were not pre-empted by some other process.

Best Answer

I don't have an answer but you might find one amongst the tools, examples and resources written or listed by Brendan Gregg on the perf command and Linux kernel ftrace and debugfs.

On my Raspberry Pi these tools were in package perf-tools-unstable. The perf command was actually in /usr/bin/perf_3.16.

Of interest may be this discussion and context-switch benchmark by Benoit Sigoure, and the lat_ctx test from the fairly old lmbench suite.

They may need some work to run on the Pi, for example with tsuna/contextswitch I edited timectxswws.c get_iterations() to while (iterations * ws_pages * 4096UL < 4294967295UL) {, and removed -march=native -mno-avx from the Makefile.

Using perf record for 10 seconds on the Pi over ssh whilst simultaneously doing while sleep .1;do echo hi;done in another ssh:

sudo timeout -10 perf_3.16 record -e context-switches -a
sudo perf_3.16 script -f time,pid,comm | less

gives output like this

           sleep 29341 2703976.560357: 
         swapper     0 2703976.562160: 
    kworker/u8:2 29163 2703976.564901: 
         swapper     0 2703976.565737: 
            echo 29342 2703976.565768: 
     migration/3    19 2703976.567549: 
           sleep 29343 2703976.570212: 
     kworker/0:0 28906 2703976.588613: 
     rcu_preempt     7 2703976.609261: 
           sleep 29343 2703976.670674: 
            bash 29066 2703976.671654: 
            echo 29344 2703976.675065: 
            sshd 29065 2703976.675454: 
         swapper     0 2703976.677757:

presumably showing when a context-switch event happened, for which process.

Related Question