VisualVM java profiling - self time execution?

Question

I have the following Java method:

static Board board;
static int[][] POSSIBLE_PLAYS; // [262143][0 - 81]

public static void playSingleBoard() {
    int subBoard = board.subBoards[board.boardIndex];
    int randomMoveId = generateRandomInt(POSSIBLE_PLAYS[subBoard].length);
    board.play(board.boardIndex, POSSIBLE_PLAYS[subBoard][randomMoveId]);
}

Accessed arrays do not change at runtime. The method is always called by the same thread. board.boardIndex may change from 0 to 8, there is a total of 9 subBoards.

In VisualVM I end up with the method being executed 2 228 212 times, with (Total Time CPU):

Self Time 27.9%
Board.play(int, int) 24.6%
MainClass.generateRnadomInt(int) 8.7%

What I am wondering is where does come from those 27.9% of self execution (999ms / 2189ms). I first thought that allocating 2 int could slow down the method so I tried the following:

public static void playSingleBoard() {
    board.play(
     board.boardIndex,
     POSSIBLE_PLAYS[board.subBoards[board.boardIndex]]
     [generateRandomInt(POSSIBLE_PLAYS[board.subBoards[board.boardIndex]].length)]
    );
}

But ending up with similar results, I have no clue what this self execution time can be.. is it GC time? memory access?

I have tried with JVM options mentionnned here => VisualVM - strange self time and without.

do you measure self time or self time(cpu)? what's the average absolute execution time of the method i.e. 27% of what? do the accessed arrays change during runtime? is the method always called by the same thread? is the method called for different boards / subboards? how many boards / subboards do you have, resp. how many entries of the arrays are accessd? — rmunge, Jun 20 '21 at 14:55

score 2 · Accepted Answer · answered Jun 20 '21 at 17:23

First, Visual VM (as well as many other safepoint-based profilers) are inherently misleading. Try using a profiler that does not suffer from the safepoint bias. E.g. async-profiler can show not only methods, but also particular lines/bytecodes where the most CPU time is spent.

Second, in your example, playSingleBoard may indeed take relatively long. Even without a profiler, I can tell that the most expensive operations here are the numerous array accesses.

RAM is the new disk. Memory access is not free, especially the random access. Especially when the dataset is too big to fit into CPU cache. Furthermore, an array access in Java needs to be bounds-checked. Also, there are no "true" two-dimentional arrays in Java, they are rather arrays of arrays.
This means, an expression like POSSIBLE_PLAYS[subBoard][randomMoveId] will result in at least 5 memory reads and 2 bounds checks. And every time there is a L3 cache miss (which is likely for large arrays like in your case), this will result in ~50 ns latency - the time enough to execute a hundred arithmetic operations otherwise.

Thanks for the good readings, that really helps. In my code I make intensively use of arrays for fast data access and didn't take into account bound-checks, plus I took as a basis that it would always be faster to access a value into an array than creating a local variable to cache the array value. — Logan Wlv, Jun 20 '21 at 17:55

VisualVM java profiling - self time execution?

1 Answers1