CODEWITHSUNDEEP
javaperformancevisualvm
Logan Wlv
Logan Wlv

Reputation: 3724

VisualVM java profiling - self time execution?

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.

Upvotes: 0

Views: 647

Answers (1)

apangin
apangin

Reputation: 98284

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.

Upvotes: 2

Related Questions