eventstat output suddenly accounts kernel threads as userspace processes after a prolonged amount of time

I think the internal cache is stale, I need to figure out how to check for this case when PIDs are re-used.

There are a few issues that I spotted in the code:

1. The code make mistake a kernel thread as a normal user space process
2. If it thinks it is a kernel thread it puts the task name in [ ] brackets
3. The hashing is performed on the modified task name

So.. it may be that the crude kernel thread detection code failed, and then the process gets a different hash because the task name changed, and so we get a "new" hash timer entry, hence the large spike for a "new item" because the old history is wrong on incorrectly hashed timer stat.

I think the fixes needed are:

1. Add more levels of smarts into the kernel thread detection, namely:
    a) is cmdline zero length -> it is a kernel thread (should always work)
    b) is pgid of the pid zero -> it is a kernel thread (useful fallback)
    c) if can't determine above, compare against a database of known kernel threads (hacky, but consistent)

2. Keep two copies of the task name:
    a) The original
    b) The modified task name of it is a kernel thread

3. Hash on the pid, taskname, callback and timer function
    - if we get a process that dies and a new one matches a hash on that then I consider that very unlikely.

I've pushed a possible fix to my git repository: git://kernel.ubuntu.com/cking/eventstat - perhaps you can try this out. If you can't built it for the target machine I will prepare a test deb package in a PPA for you.

Actually, that does not fix it, but I can now reproduce the bug.

Interestingly, the timer_stats seem to report processes that don't exist, and the stats increase overtime on a stable system, and it can be observed using:

echo 1 | sudo tee /proc/timer_stats
watch -n 1 "cat /proc/timer_stats | grep total"

I've had my fixes running on the phone for 12950+ samples at 2Hhz and I believe the fixes I've pushed into the eventstat repo address the key issues:

1. no more huge CPU consumption after a long run time
    - fixed by re-working the timer cache into a hash table
    - fixed by reaping old expired timers that have not been used for > 600 seconds

2. fixed the weird extra CPU "total events" escalation over time:
   - improved hashing on the event information with a better and wider hash
   - optimized expensive code paths to lower the time to correlate events . This
     avoids the time between each short sample time expanding and causing us
     to measure more "total events" per sample time because the time interval
     is no longer expanded over the time delay interval.

3. misc optimizations. I've run the code through perf and gcov and worked on the
    more CPU and cache expensive code paths.

I'm going to push a new release out in the next 48 hours.

This bug was fixed in the package eventstat - 0.01.37-1

---------------
eventstat (0.01.37-1) unstable; urgency=medium

  * Makefile: bump version
  * Fix repeaped prev pointer not advancing
  * Fix resource leak on file descriptor on error exit path
  * Add auto-purge of old state timer stats to stop memory growth
  * Speed up reading and parsing of the timer stat data
  * Add some performance optimisations, better hashing and heap management
  * Make hash ident a few bytes smaller for marginal compare speedup
  * Replace hash function with one that is 3.3x faster
  * Fix hash chain growth by comparing with ident rather than an NULL field
  * Free cmdline on mask check continue path
  * Remove SIGSEGV from trapped signals list
  * constify a few more variables
  * Fix memory leak on cmdline, found by CoverityScan
  * Improve kernel thread detection on unmodified task name (LP: #1467932)
  * Compare process hashes based on original process name

 -- Colin King <email address hidden> Thu, 25 Jun 2015 16:51:00 +0100