java cpu profiling accuracy

Question

I try to ensure the accuracy of some (free) java cpu profiling tools, e.g. sjk, visualvm.

Here is a sample program to do cpu-sensitive task:

RandomStringUtils.java:

import java.util.Random;

public class RandomStringUtils {
    public String generate() {
        int leftLimit = 97; // letter 'a'
        int rightLimit = 122; // letter 'z'
        int targetStringLength = 10;
        Random random = new Random();
        StringBuilder buffer = new StringBuilder(targetStringLength);
        for (int i = 0; i < targetStringLength; i++) {
            int randomLimitedInt = leftLimit + (int)
                (random.nextFloat() * (rightLimit - leftLimit + 1));
            buffer.append((char) randomLimitedInt);
        }

        return buffer.toString();
    }
}

MainClass.java:

import java.security.MessageDigest;
import java.security.NoSuchAlgorithmException;

public class MainClass {

    public String crypt(String str) {
        if (str == null || str.length() == 0) {
            throw new IllegalArgumentException("String to encript cannot be null or zero length");
        }
        StringBuilder hexString = new StringBuilder();
        try {
            MessageDigest md = MessageDigest.getInstance("MD5");
            md.update(str.getBytes());
            byte[] hash = md.digest();
            for (byte aHash : hash) {
                if ((0xff & aHash) < 0x10) {
                    hexString.append("0" + Integer.toHexString((0xFF & aHash)));
                } else {
                    hexString.append(Integer.toHexString(0xFF & aHash));
                }
            }
        } catch (NoSuchAlgorithmException e) {
            e.printStackTrace();
        }
        return hexString.toString();
    }

    public static void main(String[] args) {
        long N = 1000 * 100;
        if (args.length > 0) {
            N = Long.parseLong(args[0], 10);
        }
        MainClass main = new MainClass();
        RandomStringUtils randomStringUtils = new RandomStringUtils();
        for (long i = 0; i < N; i++) {
            main.crypt(randomStringUtils.generate());
        }
    }
}

For example, I use sjk to sample the cpu:

java -jar sjk-plus-0.11.jar stcap -p 3113 -f main -i 5ms -t 30s -o dump.std
java -jar sjk-plus-0.11.jar flame -f dump.std -o report.html

Here my question is, why the self time of main() is so large? And it only executes the loop. Doesn't the encrypt() and generate() occupy the whole cpu?

The visualvm shows the similar result.

Does sjk consider the self time and whole time? how to show them in command line report BTW?

maybe this will help: https://stackoverflow.com/questions/14626475/visualvm-and-self-time — Ivan, Jan 02 '19 at 15:27
It looks like you are including the initial class loading/verification/initialization time. — Holger, Jan 07 '19 at 12:31

score 2 · Accepted Answer · answered Mar 11 '19 at 09:46

This is a very striking example of safepoint bias.

Below 3 flame graphs for slightly modified version of your code (see on github).

Using SJK sampling

SJK is using thread dump sampling aproach so result is skewed by safepoint bias.

Using Java Flight Recorder

JFR is not affected by safepoint bias at sampling, but symbol map generated by JIT compiler is limited to safepoint checks by default. This has negative effect for reconstructing stack traces.

While results better than thread dump sampling, you can see anomalies. E.g. Integer.toHexString time is definitely exaggerated.

Using Java Flight Recorder and additional JVM options

-XX:+UnlockDiagnosticVMOptions -XX:+DebugNonSafepoints

This tweaks to JVM start options picture becomes more accurate and detailed. -XX:+DebugNonSafepoints forces JIT compiler to generate detailed symbol maps.

Judging this example you could come to conclusion that Java Flight Recorder is universally better.

Here you could find more elaborated explanation to this phenomena.

java cpu profiling accuracy

1 Answers1