Skip to content

Commit 14ca57e

Browse files
committed
[GR-48794] Updated Insight documentation after Truffle unchained changes.
PullRequest: graal/15652
2 parents 6bc23c6 + c808947 commit 14ca57e

File tree

3 files changed

+60
-68
lines changed

3 files changed

+60
-68
lines changed

docs/tools/insight/Insight-Manual.md

Lines changed: 37 additions & 41 deletions
Original file line numberDiff line numberDiff line change
@@ -41,14 +41,16 @@ Create a `source-tracing.js` script with following content:
4141

4242
```js
4343
insight.on('source', function(ev) {
44-
print(`Loading ${ev.characters.length} characters from ${ev.name}`);
44+
if (ev.characters) {
45+
print(`Loading ${ev.characters.length} characters from ${ev.name}`);
46+
}
4547
});
4648
```
4749
Run it with GraalVM's `node` launcher adding the `--insight` instrument option.
4850
Observe what scripts are being loaded and evaluated:
4951

5052
```bash
51-
graalvm/bin/node --js.print --insight=source-tracing.js -e "print('The result: ' + 6 * 7)" | tail -n 10
53+
./bin/node --js.print --experimental-options --insight=source-tracing.js -e "print('The result: ' + 6 * 7)" | tail -n 10
5254
Loading 29938 characters from url.js
5355
Loading 345 characters from internal/idna.js
5456
Loading 12642 characters from punycode.js
@@ -77,6 +79,7 @@ var map = new Map();
7779

7880
function dumpHotness() {
7981
print("==== Hotness Top 10 ====");
82+
var count = 10;
8083
var digits = 3;
8184
Array.from(map.entries()).sort((one, two) => two[1] - one[1]).forEach(function (entry) {
8285
var number = entry[1].toString();
@@ -85,7 +88,7 @@ function dumpHotness() {
8588
} else {
8689
number = Array(digits - number.length + 1).join(' ') + number;
8790
}
88-
if (number > 10) print(`${number} calls to ${entry[0]}`);
91+
if (count-- > 0) print(`${number} calls to ${entry[0]}`);
8992
});
9093
print("========================");
9194
}
@@ -110,26 +113,19 @@ The latter is executed when the `node` process execution is over (registered via
110113
Invoke the program:
111114

112115
```bash
113-
graalvm/bin/node --js.print --insight=function-hotness-tracing.js -e "print('The result: ' + 6 * 7)"
116+
./bin/node --js.print --experimental-options --insight=function-hotness-tracing.js -e "print('The result: ' + 6 * 7)"
114117
The result: 42
115118
==== Hotness Top 10 ====
116-
543 calls to isPosixPathSeparator
117-
211 calls to E
118-
211 calls to makeNodeErrorWithCode
119-
205 calls to NativeModule
120-
198 calls to uncurryThis
121-
154 calls to :=>
122-
147 calls to nativeModuleRequire
123-
145 calls to NativeModule.compile
124-
55 calls to internalBinding
125-
53 calls to :anonymous
126-
49 calls to :program
127-
37 calls to getOptionValue
128-
24 calls to copyProps
129-
18 calls to validateString
130-
13 calls to copyPrototype
131-
13 calls to hideStackFrames
132-
13 calls to addReadOnlyProcessAlias
119+
516 calls to isPosixPathSeparator
120+
311 calls to :=>
121+
269 calls to E
122+
263 calls to makeNodeErrorWithCode
123+
159 calls to :anonymous
124+
157 calls to :program
125+
58 calls to getOptionValue
126+
58 calls to getCLIOptionsFromBinding
127+
48 calls to validateString
128+
43 calls to hideStackFrames
133129
========================
134130
```
135131

@@ -162,7 +158,7 @@ Note: Make sure the Ruby support is enabled. See [Polyglot Programming guide](..
162158
Apply the JavaScript instrument to the Ruby program. Here is what you should see:
163159

164160
```bash
165-
graalvm/bin/ruby --polyglot --insight=source-trace.js helloworld.rb
161+
./bin/ruby --polyglot --insight=source-trace.js helloworld.rb
166162
JavaScript instrument observed load of helloworld.rb
167163
Hello from GraalVM Ruby!
168164
```
@@ -195,7 +191,7 @@ Run it on top of [sieve.js](https://github.com/oracle/graal/blob/5ec71a206aa4220
195191
It is a sample script which uses a variant of the Sieve of Erathostenes to compute one hundred thousand of prime numbers:
196192

197193
```bash
198-
graalvm/bin/js --insight=function-tracing.js sieve.js | grep -v Computed
194+
./bin/js --insight=function-tracing.js sieve.js | grep -v Computed
199195
Just called :program as 1 function invocation
200196
Just called Natural.next as 17 function invocation
201197
Just called Natural.next as 33 function invocation
@@ -251,7 +247,7 @@ insight.on("enter", onEnter, Roots())
251247
Apply this script to [agent-fib.js](https://github.com/oracle/graal/blob/5ec71a206aa422078ac21be9949f8eb8918b3d3c/vm/tests/all/agentscript/agent-fib.js){:target="_blank"} using the following command:
252248

253249
```bash
254-
`js --polyglot --insight=agent.py agent-fib.js`
250+
`./bin/js --polyglot --insight=agent.py agent-fib.js`
255251
```
256252

257253
Note: Make sure the Python support is enabled. See [Polyglot Programming guide](../../reference-manual/polyglot-programming.md).
@@ -277,7 +273,7 @@ puts("Ruby: Hooks are ready!")
277273
Launch a Node.js application and instrument it with the Ruby script:
278274

279275
```bash
280-
graalvm/bin/node --js.print --experimental-options --polyglot --insight=source-tracing.rb agent-fib.js
276+
./bin/node --js.print --experimental-options --polyglot --insight=source-tracing.rb agent-fib.js
281277
Ruby: Initializing GraalVM Insight script
282278
Ruby: Hooks are ready!
283279
Ruby: observed loading of node:internal/errors
@@ -316,7 +312,7 @@ insight.on("enter", -> (ctx, frame) {
316312

317313
The above Ruby script example prints out value of variable `n` when a function `minusOne` in the [agent-fib.js](https://github.com/oracle/graal/blob/5ec71a206aa422078ac21be9949f8eb8918b3d3c/vm/tests/all/agentscript/agent-fib.js){:target="_blank"} program is called:
318314
```bash
319-
graalvm/bin/node --js.print --experimental-options --polyglot --insight=agent.rb agent-fib.js
315+
./bin/node --js.print --experimental-options --polyglot --insight=agent.rb agent-fib.js
320316
minusOne 4
321317
minusOne 3
322318
minusOne 2
@@ -343,7 +339,7 @@ cat("R: Hooks are ready!\n")
343339
Use it to trace a `test.R` program:
344340

345341
```bash
346-
graalvm/bin/Rscript --insight=agent-r.R test.R
342+
./bin/Rscript --insight=agent-r.R test.R
347343
R: Initializing GraalVM Insight script
348344
R: Hooks are ready!
349345
R: observed loading of test.R
@@ -360,14 +356,14 @@ Take, for examle, a long running program like [sieve.c](https://github.com/oracl
360356
First, execute the program on GraalVM:
361357

362358
```bash
363-
export TOOLCHAIN_PATH=`graalvm/bin/lli --print-toolchain-path`
359+
export TOOLCHAIN_PATH=`.../bin/lli --print-toolchain-path`
364360
${TOOLCHAIN_PATH}/clang agent-sieve.c -lm -o sieve
365-
graalvm/bin/lli sieve
361+
./bin/lli sieve
366362
```
367363

368364
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.
369365
The GraalVM's `lli` interpreter can then use the bitcode to interpret the program at full speed.
370-
By the way, compare the result of direct native execution via `./sieve` and interpreter speed of `graalvm/bin/lli sieve`.
366+
By the way, compare the result of direct native execution via `./sieve` and interpreter speed of `./bin/lli sieve`.
371367
It should show quite good results as for an interpreter.
372368

373369
Now focus on breaking the endless loop. You can do it with this JavaScript `agent-limit.js` Insight script:
@@ -389,7 +385,7 @@ The script counts the number of invocations of the C `nextNatural` function and
389385
Run the program as:
390386

391387
```bash
392-
graalvm/bin/lli --polyglot --insight=agent-limit.js sieve
388+
./bin/lli --polyglot --insight=agent-limit.js sieve
393389
Computed 97 primes in 181 ms. Last one is 509
394390
GraalVM Insight: nextNatural method called 1000 times. enough!
395391
at <js> :anonymous(<eval>:7:117-185)
@@ -414,7 +410,7 @@ insight.on('enter', function(ctx, frame) {
414410
Print out a message everytime a new prime is added into the filter list:
415411

416412
```bash
417-
graalvm/bin/lli --polyglot --insight=agent-limit.js sieve | head -n 3
413+
./bin/lli --polyglot --insight=agent-limit.js sieve | head -n 3
418414
found new prime number 2
419415
found new prime number 3
420416
found new prime number 5
@@ -451,7 +447,7 @@ print("Two is the result " + fib(3));
451447
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:
452448

453449
```bash
454-
graalvm/bin/node --js.print --insight=fib-trace.js fib.js
450+
./bin/node --js.print --experimental-options --insight=fib-trace.js fib.js
455451
fib for 3
456452
fib for 2
457453
fib for 1
@@ -539,7 +535,7 @@ insight.on('enter', function(ctx, frame) {
539535
```
540536
That gives us:
541537
```bash
542-
graalvm/bin/js --insight=distance-trace.js distance.js
538+
./bin/js --insight=distance-trace.js distance.js
543539
Squares: 9, 16
544540
Loop var i = 0
545541
Loop var i = 1
@@ -577,7 +573,7 @@ Then it removes the probes using `insight.off` and invokes the actual `initializ
577573
The script can be run with:
578574

579575
```js
580-
graalvm/bin/node --js.print --insight=agent-require.js yourScript.js
576+
./bin/node --js.print --experimental-options --insight=agent-require.js yourScript.js
581577
```
582578

583579
This initialization sequence is known to work on GraalVM's `node` version 12.10.0 launched with the main `yourScript.js` parameter.
@@ -615,7 +611,7 @@ The `term.js` instrument waits for a call to `log` function with message `are` a
615611
As a result one gets:
616612

617613
```bash
618-
graalvm/bin/js --polyglot --insight=term.js seq.js
614+
./bin/js --polyglot --insight=term.js seq.js
619615
Hello GraalVM Insight!
620616
How
621617
great you are!
@@ -700,7 +696,7 @@ Repeating the computation fifty times gives the runtime a chance to warm up and
700696
Here is the optimal run:
701697

702698
```bash
703-
graalvm/bin/js sieve.js | grep -v Computed
699+
./bin/js sieve.js | grep -v Computed
704700
Hundred thousand prime numbers in 75 ms
705701
Hundred thousand prime numbers in 73 ms
706702
Hundred thousand prime numbers in 73 ms
@@ -709,7 +705,7 @@ Hundred thousand prime numbers in 73 ms
709705
Now compare it to execution time when running with the GraalVM Insight script enabled:
710706

711707
```bash
712-
graalvm/bin/js --insight=function-count.js sieve.js | grep -v Computed
708+
./bin/js --insight=function-count.js sieve.js | grep -v Computed
713709
Hundred thousand prime numbers in 74 ms
714710
Hundred thousand prime numbers in 74 ms
715711
Hundred thousand prime numbers in 75 ms
@@ -739,7 +735,7 @@ function Filter(number) {
739735
First, test the behavior by invoking the computation fifty times and measuring time it takes to finish the last round:
740736

741737
```bash
742-
graalvm/bin/js -e "var count=50" --file sieve.js | grep Hundred | tail -n 1
738+
./bin/js -e "var count=50" --file sieve.js | grep Hundred | tail -n 1
743739
Hundred thousand prime numbers in 73 ms
744740
```
745741

@@ -775,7 +771,7 @@ When the main loop in `measure` is over, e.g., there are hundred thousand prime
775771
Now try the following:
776772

777773
```bash
778-
graalvm/bin/js -e "var count=50" --insight=sieve-filter1.js --file sieve.js | grep Hundred | tail -n 2
774+
./bin/js -e "var count=50" --insight=sieve-filter1.js --file sieve.js | grep Hundred | tail -n 2
779775
Hundred thousand prime numbers from 2 to 1299709 has sum 62260698721
780776
Hundred thousand prime numbers in 74 ms
781777
```
@@ -847,7 +843,7 @@ Save the code snippet as a `dump.js` file.
847843
Get the [sieve.js](https://github.com/oracle/graal/blob/5ec71a206aa422078ac21be9949f8eb8918b3d3c/vm/benchmarks/agentscript/sieve.js){:target="_blank"} file and launch it as:
848844

849845
```bash
850-
graalvm/bin/js --insight=dump.js --heap.dump=dump.hprof --file sieve.js
846+
./bin/js --insight=dump.js --heap.dump=dump.hprof --file sieve.js
851847
```
852848

853849
![Heap Stack](img/Insight-HeapStack.png)

docs/tools/insight/Insight-Tracing.md

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -14,7 +14,7 @@ The following examples will demonstrate the tracing capabilities with GraalVM In
1414
To start, install the Jaeger's client side instrumentation library for Node.js:
1515

1616
```bash
17-
graalvm/bin/npm install [email protected]
17+
./bin/npm install [email protected]
1818
```
1919

2020
Now you can use the [OpenTracing API](https://github.com/opentracing/opentracing-javascript) provided by the `jaeger-client` module in your instrument `agent.js` via the `tracer` object (once it becomes available, it will discussed later in this guide):
@@ -157,7 +157,7 @@ docker run -d --name jaeger \
157157
-p 5778:5778 -p 16686:16686 -p 14268:14268 -p 9411:9411 \
158158
jaegertracing/all-in-one:latest
159159

160-
graalvm/bin/node --insight=agent.js server.js
160+
./bin/node --insight=agent.js server.js
161161
Providing Jaeger object to the agent
162162
agent: Jaeger tracer obtained
163163
Initializing Jaeger Tracer with RemoteReporter and ConstSampler(always)

docs/tools/insight/README.md

Lines changed: 21 additions & 25 deletions
Original file line numberDiff line numberDiff line change
@@ -27,12 +27,14 @@ To learn about Insight on versions 20.0 and 19.3, proceed [here](https://github.
2727
1. Create a simple _source-tracing.js_ script with the following content:
2828
```javascript
2929
insight.on('source', function(ev) {
30-
print(`Loading ${ev.characters.length} characters from ${ev.name}`);
30+
if (ev.characters) {
31+
print(`Loading ${ev.characters.length} characters from ${ev.name}`);
32+
}
3133
});
3234
```
33-
2. Having set `JAVA_HOME` to the GraalVM home directory, start the `node` launcher with the `--insight` tool and observe what scripts are being loaded and evaluated:
35+
2. Having installed the [Node.js runtime](https://github.com/oracle/graaljs/blob/master/docs/user/NodeJS.md#nodejs-runtime), start the `node` launcher with the `--insight` tool and observe what scripts are being loaded and evaluated:
3436
```shell
35-
$JAVA_HOME/bin/node --insight=source-tracing.js --js.print -e "print('The result: ' + 6 * 7)" | tail -n 10
37+
./bin/node --insight=source-tracing.js --js.print --experimental-options -e "print('The result: ' + 6 * 7)" | tail -n 10
3638
Loading 215 characters from internal/modules/esm/transform_source.js
3739
Loading 12107 characters from internal/modules/esm/translators.js
3840
Loading 1756 characters from internal/modules/esm/create_dynamic_module.js
@@ -55,6 +57,7 @@ var map = new Map();
5557

5658
function dumpHotness() {
5759
print("==== Hotness Top 10 ====");
60+
var count = 10;
5861
var digits = 3;
5962
Array.from(map.entries()).sort((one, two) => two[1] - one[1]).forEach(function (entry) {
6063
var number = entry[1].toString();
@@ -63,7 +66,7 @@ function dumpHotness() {
6366
} else {
6467
number = Array(digits - number.length + 1).join(' ') + number;
6568
}
66-
if (number > 10) print(`${number} calls to ${entry[0]}`);
69+
if (count-- > 0) print(`${number} calls to ${entry[0]}`);
6770
});
6871
print("========================");
6972
}
@@ -90,26 +93,19 @@ A table with names and counts of function invocations is printed out when the `n
9093

9194
Invoke it as:
9295
```shell
93-
$JAVA_HOME/bin/node --insight=function-hotness-tracing.js --js.print -e "print('The result: ' + 6 * 7)"
96+
./bin/node --insight=function-hotness-tracing.js --js.print --experimental-options -e "print('The result: ' + 6 * 7)"
9497
The result: 42
9598
==== Hotness Top 10 ====
96-
543 calls to isPosixPathSeparator
97-
211 calls to E
98-
211 calls to makeNodeErrorWithCode
99-
205 calls to NativeModule
100-
198 calls to uncurryThis
101-
154 calls to :=>
102-
147 calls to nativeModuleRequire
103-
145 calls to NativeModule.compile
104-
55 calls to internalBinding
105-
53 calls to :anonymous
106-
49 calls to :program
107-
37 calls to getOptionValue
108-
24 calls to copyProps
109-
18 calls to validateString
110-
13 calls to copyPrototype
111-
13 calls to hideStackFrames
112-
13 calls to addReadOnlyProcessAlias
99+
516 calls to isPosixPathSeparator
100+
311 calls to :=>
101+
269 calls to E
102+
263 calls to makeNodeErrorWithCode
103+
159 calls to :anonymous
104+
157 calls to :program
105+
58 calls to getOptionValue
106+
58 calls to getCLIOptionsFromBinding
107+
48 calls to validateString
108+
43 calls to hideStackFrames
113109
========================
114110
```
115111

@@ -132,7 +128,7 @@ puts 'Hello from GraalVM Ruby!'
132128
```
133129
3. Apply the JavaScript instrument to the Ruby program:
134130
```shell
135-
$JAVA_HOME/bin/ruby --jvm --polyglot --insight=source-trace.js helloworld.rb
131+
./bin/ruby --polyglot --insight=source-trace.js helloworld.rb
136132
JavaScript instrument observed load of helloworld.rb
137133
Hello from GraalVM Ruby!
138134
```
@@ -152,7 +148,7 @@ puts 'Ruby: Hooks are ready!'
152148

153149
2. Launch a Node.js application and instrument it with the Ruby script:
154150
```shell
155-
$JAVA_HOME/bin/node --jvm --polyglot --insight=source-tracing.rb --js.print -e "print('With Ruby: ' + 6 * 7)" | grep Ruby
151+
./bin/node --polyglot --insight=source-tracing.rb -e "console.log('With Ruby: ' + 6 * 7)" | grep Ruby
156152
Ruby: Initializing GraalVM Insight script
157153
Ruby: Hooks are ready!
158154
Ruby: observed loading of internal/per_context/primordials.js
@@ -196,7 +192,7 @@ print("Two is the result " + fib(3));
196192

197193
When the instrument is stored in a `fib-trace.js` file and the actual code is in `fib.js`, invoking the following command yields detailed information about the program execution and parameters passed between function invocations:
198194
```shell
199-
$JAVA_HOME/bin/node --insight=fib-trace.js --js.print fib.js
195+
./bin/node --insight=fib-trace.js --js.print --experimental-options fib.js
200196
fib for 3
201197
fib for 2
202198
fib for 1

0 commit comments

Comments
 (0)