Working on systemtap equivalent to bcc ucalls.py

Working on systemtap equivalent to bcc ucalls.py

[William Cohen]

[-- Attachment #1: Type: text/plain, Size: 3452 bytes --]

Hi,

I have been working a Systemtap script that implements similar functionality to bcc's ucalls (https://github.com/iovisor/bcc/blob/master/tools/lib/ucalls.py).  The systemtap script will count the number of function/method calls for java/python/perl/php/ruby/tcl code pointed at by the -x <pid> or -c <command> options.  It also takes an optional argument for the number of seconds between reports.  One can also control the number of printed by setting the TOP variable on the command line.  So something like this monitoring "dnf debuginfo-install kernel-4.18.17-200.fc28.x86_64"


$ ./profiling/ucalls.stp -x 22952  -G TOP=10 10
Missing separate debuginfos, use: debuginfo-install kernel-core-4.18.17-200.fc28.x86_64 
METHOD                                              # CALLS
/usr/lib/python3.6/site-packages/dnf/cli/progress.py.progress       20
/usr/lib/python3.6/site-packages/dnf/cli/format.py.format_number       20
/usr/lib64/python3.6/posixpath.py.basename               20
/usr/lib/python3.6/site-packages/dnf/repo.py._progress_cb       20
/usr/lib/python3.6/site-packages/dnf/repo.py.download_size       20
/usr/lib/python3.6/site-packages/dnf/repo.py.__str__       20
/usr/lib64/python3.6/posixpath.py._get_sep               20
/usr/lib/python3.6/site-packages/dnf/cli/progress.py._update       10
/usr/lib/python3.6/site-packages/dnf/cli/progress.py.message       10
/usr/lib/python3.6/site-packages/dnf/cli/format.py.format_time       10

METHOD                                              # CALLS
/usr/lib/python3.6/site-packages/dnf/cli/progress.py.progress       20
/usr/lib/python3.6/site-packages/dnf/cli/format.py.format_number       20
/usr/lib64/python3.6/posixpath.py.basename               20
/usr/lib/python3.6/site-packages/dnf/repo.py._progress_cb       20
/usr/lib/python3.6/site-packages/dnf/repo.py.download_size       20
/usr/lib/python3.6/site-packages/dnf/repo.py.__str__       20
/usr/lib64/python3.6/posixpath.py._get_sep               20
/usr/lib/python3.6/site-packages/dnf/cli/progress.py._update       10
/usr/lib/python3.6/site-packages/dnf/cli/progress.py.message       10
/usr/lib/python3.6/site-packages/dnf/cli/format.py.format_time       10

There are a number of other options that the bcc ucalls has that are not implemented in this systemtap script:

language "-l" <language>  : this isn't needed in the systemtap script.  systemtap optional probes allow automatic selection of the language

Latency "-L": this is possible and considering adding this.  However, the ucalls doesn't handle recursive functions.

Report syscalls "-S"  this should also be easy to add.  Need to see how ucalls outputs this.

Report in milliseconds "-m" : this didn't seem that important


One of the things I noticed when running the script with the periodic updates is that it will exist due to exceeding the overhead limits.  I think it is because the handler printing out the data takes a substantial amount of time and locks the associative array will working on it, causing the overhead to go up quite a bit for all the probes that are collecting data.

It would be nice if systemtap had some mechanism kind of like double buffering used for video displays.  Two entries for associative arrays: one for the data collection and the other for the display.  They are swapped when then time probe handler runs.  This would allow the reporting to lock the associative arrays for a much shorter period of time.

-Will

[-- Attachment #2: ucalls.stp --]
[-- Type: text/plain, Size: 1484 bytes --]

#! /usr/bin/env stap
#
# Copyright (C) 2018 Red Hat, Inc.
# By William cohen, Red Hat Inc.
# wcohen@redhat.com
#

global tally
global TOP = 100000 // -G TOP=10 to get top 10

# probes for java
probe hotspot.method_entry? {
  if (pid() != target()) next
  tally[class, name] <<< 1
}

# probes for perl
probe perl.sub.call? {
  if (pid() != target()) next
  tally[filename, sub] <<< 1
}

# probes for php
probe process("php").mark("function__entry")? {
  if (pid() != target()) next
  class = user_string($arg4)
  method = user_string($arg1)
  tally[class, method] <<< 1
}

# probes for python
probe process("/usr/lib*/libpython*.so.1.0").mark("function__entry")? {
  if (pid() != target()) next
  class = user_string($arg1)
  method = user_string($arg2)
  tally[class, method] <<< 1
}

# probes for ruby
probe ruby.method.entry? {
  if (pid() != target()) next
  tally[classname, methodname] <<< 1
}

# probes for tcl
# TODO cmd__entry ?
probe process("/usr/lib*/libtcl*.so").mark("proc__entry")? {
  if (pid() != target()) next
  class = ""
  method = user_string($arg1)
  tally[class, method] <<< 1
}

function print_info() {
  printf("%-50s %8s\n", "METHOD", "# CALLS")
  foreach([class, method] in tally- limit TOP){
    class_method = sprintf("%s.%s", class, method)
    printf("%-50s %8d\n", class_method, @sum(tally[class, method]))
  }
  printf("\n")
}

# optional periodic timer timer argument
%( $# > 0 %?
probe timer.s($1)
%:
probe end
%)
{
  print_info()
  delete tally
}