T-Trace-Manual.md

T-Trace: Hacker's Handle to the Ultimate Tracing Framework

T-Trace is multipurpose, flexible tool that greatly reduces the effort of writing reliable microservices solutions. The dynamic nature of T-Trace helps everyone to selectively apply complex tracing pointcuts on already deployed applications running at full speed. T-Trace further blurs the difference between various DevOps tasks - code once, apply your insights anytime, anywhere!

Any moderately skilled hacker can easily create own so called T-Trace snippets and dynamically apply them to the actual programs. That provides ultimate insights into execution and behavior of once application without compromising the speed of the execution. Let's get started with an obligatory Hello World example.

Hello World!

Create a simple source-tracing.js script with following content:

agent.on('source', function(ev) {
    print(`Loading ${ev.characters.length} characters from ${ev.name}`);
});

launch your GraalVM's bin/node launcher with the --agentscript instrument and observe what scripts are being loaded and evaluated:

$ graalvm/bin/node --experimental-options --js.print --agentscript=source-tracing.js -e "print('The result: ' + 6 * 7)" | tail -n 10
Loading 29938 characters from url.js
Loading 345 characters from internal/idna.js
Loading 12642 characters from punycode.js
Loading 33678 characters from internal/modules/cjs/loader.js
Loading 13058 characters from vm.js
Loading 52408 characters from fs.js
Loading 15920 characters from internal/fs/utils.js
Loading 505 characters from [eval]-wrapper
Loading 29 characters from [eval]
The result: 42

What has just happened? The T-Tracing source-tracing.js script has used the provided agent object to attach a source listener to the runtime. As such, whenever the node.js framework loaded a script, the listener got notified of it and could take an action - in this case printing the length and name of processed script.

Histogram - Use Full Power of Your Language!

Collecting the insights information isn't limited to simple print statement. One can perform any Turing complete computation in your language. Imagine following function-histogram-tracing.js that counts all method invocations and dumps the most frequent ones when the execution of your program is over:

var map = new Map();

function dumpHistogram() {
    print("==== Histogram ====");
    var digits = 3;
    Array.from(map.entries()).sort((one, two) => two[1] - one[1]).forEach(function (entry) {
        var number = entry[1].toString();
        if (number.length >= digits) {
            digits = number.length;
        } else {
            number = Array(digits - number.length + 1).join(' ') + number;
        }
        if (number > 10) print(`${number} calls to ${entry[0]}`);
    });
    print("===================");
}

agent.on('enter', function(ev) {
    var cnt = map.get(ev.name);
    if (cnt) {
        cnt = cnt + 1;
    } else {
        cnt = 1;
    }
    map.set(ev.name, cnt);
}, {
    roots: true
});

agent.on('close', dumpHistogram);

The map is a global variable shared inside of the T-Trace script that allows the code to share data between the agent.on('enter') function and the dumpHistogram function. The latter is executed when the node process execution is over (registered via agent.on('close', dumpHistogram). Invoke as:

$ graalvm/bin/node --experimental-options --js.print --agentscript=function-histogram-tracing.js -e "print('The result: ' + 6 * 7)"
The result: 42
=== Histogram ===
543 calls to isPosixPathSeparator
211 calls to E
211 calls to makeNodeErrorWithCode
205 calls to NativeModule
198 calls to uncurryThis
154 calls to :=>
147 calls to nativeModuleRequire
145 calls to NativeModule.compile
 55 calls to internalBinding
 53 calls to :anonymous
 49 calls to :program
 37 calls to getOptionValue
 24 calls to copyProps
 18 calls to validateString
 13 calls to copyPrototype
 13 calls to hideStackFrames
 13 calls to addReadOnlyProcessAlias
=================

Table with names and counts of function invocations is printed out when the node process exits.

Not Limited to Node

So far the examples used node.js, but the T-Trace system isn't tight to Node.js at all - it is available in all the environments GraalVM provides. Let's try it on bin/js - pure JavaScript implementation that comes with GraalVM. Let's define function-tracing.js script as:

var count = 0;
var next = 8;

agent.on('enter', function(ev) {
    if (count++ % next === 0) {
        print(`Just called ${ev.name} as ${count} function invocation`);
        next *= 2;
    }
}, {
    roots: true
});

and run it on top of sieve.js - a sample script which uses a variant of the Sieve of Erathostenes to compute one hundred thousand of prime numbers:

$ graalvm/bin/js --experimental-options --agentscript=function-tracing.js sieve.js | grep -v Computed
Just called :program as 1 function invocation
Just called Natural.next as 17 function invocation
Just called Natural.next as 33 function invocation
Just called Natural.next as 65 function invocation
Just called Natural.next as 129 function invocation
Just called Filter as 257 function invocation
Just called Natural.next as 513 function invocation
Just called Natural.next as 1025 function invocation
Just called Natural.next as 2049 function invocation
Just called Natural.next as 4097 function invocation

T-Trace scripts are ready to be used in any environment - be it the default node implementation, the lightweight js command line tool - or your own application that decides to embedd GraalVM scripting capabilities!

Trully Polyglot - T-Trace any Language

The previous examples were written in JavaScript, but due to the polyglot nature of GraalVM, we can take the same instrument and use it in a program written in the Ruby language. Here is an example - create source-trace.js file:

agent.on('source', function(ev) {
   if (ev.uri.indexOf('gems') === -1) {
     let n = ev.uri.substring(ev.uri.lastIndexOf('/') + 1);
     print('JavaScript instrument observed load of ' + n);
   }
});

and prepare your Ruby file helloworld.rb (make sure GraalVM Ruby is installed with gu install ruby):

puts 'Hello from GraalVM Ruby!'

when you apply the JavaScript instrument to the Ruby program, here is what you get:

$ graalvm/bin/ruby --polyglot --experimental-options --agentscript=source-trace.js helloworld.rb
JavaScript instrument observed load of helloworld.rb
Hello from GraalVM Ruby!

It is necessary to start GraalVM's Ruby launcher with --polyglot parameter as the source-tracing.js script remains written in JavaScript. That's all fine - mixing languages has never been a problem for GraalVM!

Minimal Overhead

With all the power the T-Trace framework brings, it is fair to ask what's the overhead when the insights are applied? The overhead of course depends on what your scripts do. When they add and spread complex computations all around your code base, then the price for the computation will be payed. However, that would be overhead of your code, not of the instrumentation! Let's thus measure overhead of a simple function-count.js script:

var count = 0;
function dumpCount() {
    print(`${count} functions have been executed`);
}

agent.on('enter', function(ev) {
    count++;
}, {
    roots: true
});

agent.on('close', dumpCount);

Let's use the script on fifty iterations of sieve.js sample which uses a variant of the Sieve of Erathostenes to compute one hundred thousand of prime numbers. Repeating the computation fifty times gives the runtime a chance to warm up and properly optimize. Here is the optimal run:

$ graalvm/bin/js sieve.js | grep -v Computed
Hundred thousand prime numbers in 75 ms
Hundred thousand prime numbers in 73 ms
Hundred thousand prime numbers in 73 ms

and now let's compare it to execution time when running with the T-Trace script enabled:

$ graalvm/bin/js --experimental-options --agentscript=function-count.js sieve.js  | grep -v Computed
Hundred thousand prime numbers in 74 ms
Hundred thousand prime numbers in 74 ms
Hundred thousand prime numbers in 75 ms
72784921 functions have been executed

Two milliseconds!? Seriously? Yes, seriously. The T-Trace framework blends the difference between application code and insight gathering scripts making all the code work as one! The count++ invocation becomes natural part of the application at all the places representing ROOT of application functions. T-Trace system gives you unlimited instrumentation power at no cost!

Trully Polyglot - T-Tracing with Ruby

Not only one can instrument any GraalVM language, but also the T-Trace scripts can be written in any GraalVM supported language. Take for example Ruby and create source-tracing.rb (make sure GraalVM Ruby is installed via gu install ruby) file:

puts "Ruby: Initializing T-Trace script"

agent.on('source', ->(ev) {
    name = ev[:name]
    puts "Ruby: observed loading of #{name}" 
})

puts 'Ruby: Hooks are ready!'

and then you can launch your node application and instrument it with such Ruby written script:

$ graalvm/bin/node --experimental-options --js.print --polyglot --agentscript=source-tracing.rb -e "print('With Ruby: ' + 6 * 7)" | grep Ruby:
Ruby: Initializing T-Trace script
Ruby: Hooks are ready!
Ruby: observed loading of internal/per_context/primordials.js
Ruby: observed loading of internal/per_context/setup.js
Ruby: observed loading of internal/per_context/domexception.js
....
Ruby: observed loading of internal/modules/cjs/loader.js
Ruby: observed loading of vm.js
Ruby: observed loading of fs.js
Ruby: observed loading of internal/fs/utils.js
Ruby: observed loading of [eval]-wrapper
Ruby: observed loading of [eval]
With Ruby: 42

Write your T-Trace scripts in any language you wish! They'll be ultimatelly useful accross the whole GraalVM ecosystem.

Trully Polyglot - T-Tracing with R

The same instrument can be written in the R language opening tracing and aspect based programing to our friendly statistical community. Just create agent-r.R script:

cat("R: Initializing T-Trace script\n")

agent@on('source', function(env) {
    cat("R: observed loading of ", env$name, "\n")
})

cat("R: Hooks are ready!\n")

and use it to trace your test.R program:

$ graalvm/bin/Rscript --agentscript=agent-r.R --experimental-options test.R
R: Initializing T-Trace script
R: Hooks are ready!
R: observed loading of test.R

The only change is the R language. All the other T-Trace features and APIs remain the same.

Inspecting Values

T-Trace not only allows one to trace where the program execution is happening, but it also offers access to values of local variables and function arguments during execution. One can for example write instrument that shows value of argument n in a function fib:

agent.on('enter', function(ctx, frame) {
   print('fib for ' + frame.n);
}, {
   roots: true,
   rootNameFilter: (name) => 'fib' === name
});

This instrument uses second function argument frame to get access to values of local variables inside of every instrumented function. The above T-Trace script also uses rootNameFilter to apply its hook only to function named fib:

function fib(n) {
  if (n < 1) return 0;
  if (n < 2) return 1;
  else return fib(n - 1) + fib(n - 2);
}
print("Two is the result " + fib(3));

When the instrument is stored in a fib-trace.js file and the actual code in fib.js, then invoking following command yields detailed information about the program execution and parameters passed between function invocations:

$ graalvm/bin/node --experimental-options --js.print --agentscript=fib-trace.js fib.js
fib for 3
fib for 2
fib for 1
fib for 0
fib for 1
Two is the result 2

T-Trace is a perfect tool for polyglot, language agnostic aspect oriented programming!

API of T-Trace

The T-Trace functionality is offered as a technology preview and requires one to use --experimental-options to enable the --agentscript instrument. Never the less, the compatibility of the T-Trace API exposed via the agent object is treated seriously.

The documentation of the agent object properties and functions is available as part of its javadoc.

Future versions will add new features, but whatever has once been exposed, remains functional. If your script depends on some fancy new feature, it may check version of the exposed API:

print(`Agent version is ${agent.version}`);

and act accordingly to the obtained version. New elements in the documentation carry associated @since tag to describe the minimimal version the associated functionality/element is available since.

Delaying T-Trace Initialization in node.js

T-Trace can be used in any GraalVM enabled environment including GraalVM's node implementation. However, when in node, one doesn't want to write plain simple T-Trace scripts - one wants to use full power of node ecosystem including its modules. Here is a sample agent-require.js script that does it:

let initializeAgent = function (require) {
    let http = require("http");
    print(`${typeof http.createServer} http.createServer is available to the agent`);
}

let waitForRequire = function (event) {
  if (typeof process === 'object' && process.mainModule && process.mainModule.require) {
    agent.off('source', waitForRequire);
    initializeAgent(process.mainModule.require);
  }
};

agent.on('source', waitForRequire, { roots: true });

The script solves an important problem: T-Trace agents are initialized as soon as possible and at that moment the require function isn't yet ready. As such the agent first attaches a listener on loaded scripts and when the main user script is being loaded, it obtains its process.mainModule.require function. Then it removes the probes using agent.off and invokes the actual initializeAgent function to perform the real initialization while having access to all the node modules. The script can be used as

$ graalvm/bin/node --experimental-options --js.print --agentscript=agent-require.js yourScript.js

This initialization sequence is known to work on GraalVM's node v12.10.0 launched with a main yourScript.js parameter.

Handling Exceptions

The T-Trace agents can throw exceptions which are then propagated to the surrounding user scripts. Imagine you have a program seq.js logging various messages:

function log(msg) {
    print(msg);
}

log('Hello T-Trace!');
log('How');
log('are');
log('You?');

You can register an instrument term.js and terminate the execution in the middle of the seq.js program execution based on observing the logged message:

agent.on('enter', (ev, frame) => { 
    if (frame.msg === 'are') {
        throw 'great you are!';
    }
}, {
    roots: true,
    rootNameFilter: (n) => n === 'log'
});

The term.js instrument waits for a call to log function with message 'are' and at that moment it emits its own exception effectively interrupting the user program execution. As a result one gets:

$ graalvm/bin/js --polyglot --experimental-options --agentscript=term.js seq.js
Hello T-Trace!
How
great you are!
        at <js> :=>(term.js:3:75-97)
        at <js> log(seq.js:1-3:18-36)
        at <js> :program(seq.js:7:74-83)

The exceptions emitted by T-Trace instruments are treated as regular language exceptions. The seq.js program could use regular try { ... } catch (e) { ... } block to catch them and deal with them as if they were emitted by the regular user code.

Hack into the C Code!

The polyglot capabilities of GraalVM know no limits. Not only it is possible to interpret dynamic languages, but with the help of the lli launcher one can mix in even statically compiled programs written in C, C++, Fortran, Rust, etc.

Imagine you have a long running program just like sieve.c (which contains never-ending for loop in main method) and you'd like to give it some execution quota. That is quite easy to do with GraalVM and T-Trace! First of all execute the program on GraalVM:

$ export TOOLCHAIN_PATH=`graalvm/bin/lli --print-toolchain-path`
$ ${TOOLCHAIN_PATH}/clang agent-sieve.c -lm -o sieve
$ graalvm/bin/lli sieve

Why toolchain? The GraalVM clang wrapper adds special options instructing the regular clang to keep the LLVM bitcode information in the sieve executable along the normal native code. The GraalVM's lli interpreter can then use the bitcode to interpret the program at full speed. Btw. compare the result of direct native execution via ./sieve and interpreter speed of graalvm/bin/lli sieve - quite good result for an interpreter, right?

Anyway let's focus on breaking the endless loop. You can do it with a JavaScript agent-limit.js T-Trace script:

var counter = 0;

agent.on('enter', function(ctx, frame) {
    if (++counter === 1000) {
        throw `T-Trace: ${ctx.name} method called ${counter} times. enough!`;
    }
}, {
    roots: true,
    rootNameFilter: (n) => n === 'nextNatural'
});

The script counts the number of invocations of the C nextNatural function and when the function gets invoked a thousand times, it emits an error to terminate the sieve execution. Just run the program as:

$ lli --polyglot --agentscript=agent-limit.js --experimental-options sieve
Computed 97 primes in 181 ms. Last one is 509
T-Trace: nextNatural method called 1000 times. enough!
        at <js> :anonymous(<eval>:7:117-185)
        at <llvm> nextNatural(agent-sieve.c:14:186-221)
        at <llvm> nextPrime(agent-sieve.c:74:1409)
        at <llvm> measure(agent-sieve.c:104:1955)
        at <llvm> main(agent-sieve.c:123:2452)

The mixture of lli, polyglot and T-Trace opens enormous possibilities in tracing, controlling and interactive or batch debugging of native programs. Write in C, C++, Fortran, Rust and inspect with JavaScript, Ruby & co.!