“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:

Everything you need to grow your career. With your free Red Hat Developer program membership, unlock our library of cheat sheets and ebooks on next-generation application development. SIGN UP

# 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.