"Use the dynamic tracing tools, Luke"

A common refrain for tracking down issues on computer systems running open source software is "Use the source, Luke." Reviewing the source code can be helpful in understanding how the code works, but the static view may not give you a complete picture of how things work (or are broken) in the code. The paths taken through code are heavily data dependent. Without knowledge about specific values at key locations in code, you can easily miss what is happening. Dynamic instrumentation tools, such as SystemTap, that trace and instrument the software can help provide a more complete understanding of what the code is actually doing

I have wanted to better understand how the Ruby interpreter works. This is an opportunity to use SystemTap to investigate Ruby MRI internals on Red Hat Enterprise Linux 7. The article What is SystemTap and how to use it? has more information about installing SystemTap. The x86_64 RHEL 7 machine has ruby-2.0.0648-33.el7_4.x86_64.rpm installed, so the matching debuginfo RPM is installed to provide SystemTap with information about function parameters and to provide me with human-readable source code. The debuginfo RPM is installed by running the following command as root:

# debuginfo-install ruby -y

The first thing I notice is the Ruby command /usr/bin/ruby is very small, less than 8K bytes in size:

$ ls -l /usr/bin/ruby
-rwxr-xr-x. 1 root root 7184 Feb 19 07:12 /usr/bin/ruby

The actual interpreter must be located elsewhere. I look through the shared libraries used by /usr/bin/ruby and find libruby.so.2.0 as a likely home of the Ruby interpreter:

$ ldd /usr/bin/ruby
	linux-vdso.so.1 =>  (0x00007ffc11076000)
	libruby.so.2.0 => /lib64/libruby.so.2.0 (0x00007f8a62a1a000)
	libpthread.so.0 => /lib64/libpthread.so.0 (0x00007f8a627fe000)
	librt.so.1 => /lib64/librt.so.1 (0x00007f8a625f6000)
	libdl.so.2 => /lib64/libdl.so.2 (0x00007f8a623f2000)
	libcrypt.so.1 => /lib64/libcrypt.so.1 (0x00007f8a621bb000)
	libm.so.6 => /lib64/libm.so.6 (0x00007f8a61eb9000)
	libc.so.6 => /lib64/libc.so.6 (0x00007f8a61aec000)
	/lib64/ld-linux-x86-64.so.2 (0x00007f8a62e77000)
	libfreebl3.so => /lib64/libfreebl3.so (0x00007f8a618e9000)

We can list out the all the functions in the shared library that SystemTap can probe using the wildcard "*" to match all function names:

$ stap -l 'process("/lib64/libruby.so.2.0").function("*")'

There are over 5600 functions visible to SystemTap in the Ruby MRI interpreter. Instrumenting all of these functions is probably going to give us information overload. Also, SystemTap checks to see how much overhead its instrumentation introduces into the code and will stop if it is causing too much overhead. Let's reduce the scope and just look at how Ruby's arbitrary precision arithmetic works. The following shows the 125 various functions associated with bignum:

$ stap -l 'process("/lib64/libruby.so.2.0").function("*")'|grep "bignum"

Below, is a single line of the output from the stap -l command above for the function rb_cstr_to_inum in the Ruby MRI shared library /usr/lib64/libruby.so.2.0.0. This line has additional information following the function name after the @ sign: the source file and line number for this function.

process("/usr/lib64/libruby.so.2.0.0").function("rb_cstr_to_inum@/usr/src/debug/ruby-2.0.0-p648/bignum.c:579")

As mentioned earlier, the Ruby debuginfo provides the bignum.c source file. Loading that file in the editor and going to line 579 shows the start of that function:

VALUE
rb_cstr_to_inum(const char *str, int base, int badcheck)
{
const char *s = str;
char *end;
char sign = 1, nondigit = 0;
int c;
...

The SystemTap wildcard can be specified to limit the matching to just functions in the bignum.c file, as shown below:

$ stap -l 'process("/lib64/libruby.so.2.0").function("*@*/bignum.c")'

Now, with armed with this collection of probe-able functions, we can look at how the arbitrary precision arithmetic operates using the SystemTap example script para-callgraph.stp in /usr/share/systemtap/examples/general/para-callgraph.stp. Ruby source code has a sample program, pi.rb, that computes the digits of pi using the arbitrary precision arithmetic.

$ more pi.rb
#!/usr/local/bin/ruby

k, a, b, a1, b1 = 2, 4, 1, 12, 4

loop do
  # Next approximation
  p, q, k = k*k, 2*k+1, k+1
  a, b, a1, b1 = a1, b1, p*a+q*a1, p*b+q*b1
  # Print common digits
  d = a / b
  d1 = a1 / b1
  while d == d1
    print d
    $stdout.flush
    a, a1 = 10*(a%b), 10*(a1%b1)
    d, d1 = a/b, a1/b1
  end
end

It will run, printing out the never-ending stream of digits of pi:

$ ruby pi.rb
3141592653589793238462643383279502884197169399375105820974944592
3078164062862089986280348253421170679821480865132823066470938446
0955058223172535940812848111745028410270193852110555964462294895
4930381964428810975665933446128475648233786783...

Now we can see how the arbitrary arithmetic functions operate during the program execution. The first line of the command below invokes SystemTap with the para-callgraph.stp script. The second line provides the script with the information about which functions to probe. In this case, all the functions from the bignum.c source file are traced. The last line of the command makes SystemTap start the ruby program once all the SystemTap instrumentation has been created. The pi.rb program will run endlessly. Once we have enough trace data, we can stop the program and tracing by pressing Ctrl-C.

stap /usr/share/systemtap/examples/general/para-callgraph.stp \
'process("/lib64/libruby.so.2.0").function("*@*/bignum.c")' \
-c "ruby pi.rb"

Below is the start of the output. Approximately 25 digits are printed out before we see para-callgraph.stp output for the call to rb_big_resize_big. This might be a side effect of buffering output rather than the actual order in which things occurred. Each line of the para-callgraph.stp starts with the number of microseconds elapsed from the previous line, the process name, and the PID. The -> indicates entering a function function with its list of argument values. The <- is the return from the from the function with a return value, if it has one. Nested function calls are indented.

At the very beginning of the program trace, we can see some initialization including a call to Init_Bignum. The source for the Init_Bignum function show a series of calls to set up the various methods in the class using the rb_define_method function, which is in a file other than bignum.c and is not instrumented. Thus, there is no tracing of the rb_define_method function. However, there is a call to the rb_uint2big function at the end of Init_Bignum and this is seen in the trace. The rb_uint2big source code has bignew in it with two arguments in the code, but in the trace there is bignew_1 invoked with three arguments. Searching through the bignum.c shows a define that converts bignew into a call to bignew_1 with three arguments.

We also see a conversion of a string with the first rb_cstr_to_inum that is base 8 (0x8) and returns 0x5. The next conversion by rb_cstr_to_inum from strings to number is base 10 (0xa) and returns 0x3. The source code shows that rb_cstr_to_inum returns the value from bignorm, but there is no trace of bignorm in the trace. The compiler optimized the code by inlining bignorm into rb_cstr_to_inum to eliminate the cost of the function call. The values returned by bignorm (and rb_cstr_to_inum) use the low bit to indicate the object type (How Big is a Bignum?). In rb_cstr_to_inum, the objects have the least-significant bit set indicating the values are fixed numbers.

31415926535897932384626433     0 ruby(6049):->rb_big_resize big=0x201bfb0 len=0x5
     5 ruby(6049):rb_big_norm x=0x201bfb0
     2 ruby(6049): ->bignorm x=0x201bfb0
     4 ruby(6049):  ->rb_big_resize big=0x201bfb0 len=0x4
     7 ruby(6049):  <-rb_big_resize 
     8 ruby(6049): <-bignorm return=0x201bfb0
     9 ruby(6049):Init_Bignum 
    25 ruby(6049): ->rb_uint2big n=0x3
    28 ruby(6049):  ->bignew_1 klass=0x20168a8 len=0x2 sign=0x1
    31 ruby(6049):  <-bignew_1 return=0x2016858
    33 ruby(6049): <-rb_uint2big return=0x2016858
    36 ruby(6049):rb_uint2big n=0xffffffffffffffff
     4 ruby(6049): ->bignew_1 klass=0x20168a8 len=0x2 sign=0x1
     6 ruby(6049): <-bignew_1 return=0x200b4a8
     8 ruby(6049):rb_cstr_to_inum str=0x2122390 base=0x8 badcheck=0x0
     6 ruby(6049):rb_cstr_to_inum str=0x2122390 base=0xa badcheck=0x0
     3 ruby(6049):<-rb_cstr_to_inum return=0x3

Earlier examination of the Init_Bignum function code showed that the / (divide) method is performed by the rb_big_div function. Since pi.rb performs division, there should be calls to rb_big_div. A bit later in the trace output, there is an example of a divide operation on arbitrary precision arithmetic by the rb_big_div function. It calls rb_big_divide with the argument op=0x2f, an ASCII character /. The trace shows an argument needed to be converted to the proper class with a call to rb_int2big before passing the values to bigdivmod. The bigdivrem and bigdivrem1 functions do the actual division. Once the divide operation is done, another normalization is done by the bignorm function to determine how large the result is and size the storage appropriately. In this particular case, the value (0xb) has the low bit set indicating the value is a fixed number with the numerical value coded in the remaining bits of the return value.

     0 ruby(6049):->rb_big_div x=0x238abd8 y=0x63c25f1981ac4201
     3 ruby(6049): ->rb_big_divide x=0x238abd8 y=0x63c25f1981ac4201 op=0x2f
     6 ruby(6049):  ->rb_int2big n=0x31e12f8cc0d62100
     8 ruby(6049):   ->rb_uint2big n=0x31e12f8cc0d62100
    11 ruby(6049):    ->bignew_1 klass=0x20168a8 len=0x2 sign=0x1
    13 ruby(6049):    <-bignew_1 return=0x238abb0
    15 ruby(6049):   <-rb_uint2big return=0x238abb0
    16 ruby(6049):  bigdivmod x=0x238abd8 y=0x238abb0 divp=0x7fff57542938 modp=0x0
    22 ruby(6049):   ->bigdivrem x=0x238abd8 y=0x238abb0 divp=0x7fff57542938 modp=0x7fff575428e8
    24 ruby(6049):    ->bignew_1 klass=0x20168a8 len=0x4 sign=0x1
    27 ruby(6049):    rb_big_clone x=0x238abb0
    31 ruby(6049):     ->bignew_1 klass=0x20168a8 len=0x2 sign=0x1
    34 ruby(6049):     <-bignew_1 return=0x238ab60
    36 ruby(6049):    bigdivrem1 ptr=0x7fff57542860
    41 ruby(6049):    rb_big_clone x=0x238ab88
    45 ruby(6049):     ->bignew_1 klass=0x20168a8 len=0x4 sign=0x1
    47 ruby(6049):     <-bignew_1 return=0x238ab38
    48 ruby(6049):    rb_big_clone x=0x238ab88
    62 ruby(6049):     ->bignew_1 klass=0x20168a8 len=0x4 sign=0x1
    64 ruby(6049):     <-bignew_1 return=0x238ab10
    66 ruby(6049):    <-rb_big_clone return=0x238ab10
    67 ruby(6049):   <-bigdivrem return=0x238ab88
    69 ruby(6049):  bignorm x=0x238ab38
    82 ruby(6049):  <-bignorm return=0xb
    84 ruby(6049): <-rb_big_divide return=0xb
    85 ruby(6049):<-rb_big_div return=0xb

As a result of this little exercise, I have a bit better understanding of how the Ruby interpreter handles arbitrary arithmetic. This same technique can be used to trace out the execution of other parts of Ruby MRI (or any other complicated piece of software) to better understand how it operates.