0

I want to measure the startup time of a server without a considerable overhead.

What I actually want to measure is the time from server process execution to the time that the server starts listening to a well-known port.

For example, I want to measure the startup time of a simple Netty Server. i.e. the time from startup to the time it is ready to accept requests.

I developed a Java Agent using Byte-Buddy.

public class Agent {

public static void premain(String arg, Instrumentation instrumentation) {
    new AgentBuilder.Default()
            .type(ElementMatchers.named("io.netty.bootstrap.AbstractBootstrap"))
            .transform((builder, typeDescription, classLoader, javaModule) ->
                    builder.visit(Advice.to(TimeAdvice.class)
                            .on(ElementMatchers.named("bind").and(ElementMatchers.takesArguments(SocketAddress.class)))))
            .installOn(instrumentation);
}
}

Following is the source code for TimeAdvice

public class TimeAdvice {

@Advice.OnMethodExit
static void exit(@Advice.Origin String method) {
    System.out.println(String.format("Server started. Current Time (ms): %d", System.currentTimeMillis()));
    System.out.println(String.format("Server started. Current Uptime (ms): %d",
            ManagementFactory.getRuntimeMXBean().getUptime()));
}
}

With this agent, the startup time is around 1400ms. However, when I measure the startup time by modifying the server code, the startup time of the server is around 650ms.

Therefore, it seems that there is a considerable overhead with byte-buddy Java agent when considering the startup time.

I also tried another Java Agent with Javassist.

public class Agent {

private static final String NETTY_CLASS = "io/netty/bootstrap/AbstractBootstrap";

public static void premain(String arg, Instrumentation instrumentation) {
    instrumentation.addTransformer((classLoader, s, aClass, protectionDomain, bytes) -> {
        if (NETTY_CLASS.equals(s)) {
            System.out.println(aClass);
            long start = System.nanoTime();
            // Javassist
            try {
                ClassPool cp = ClassPool.getDefault();
                CtClass cc = cp.get("io.netty.bootstrap.AbstractBootstrap");
                CtMethod m = cc.getDeclaredMethod("bind", new CtClass[]{cp.get("java.net.SocketAddress")});
                m.insertAfter("{ System.out.println(\"Server started. Current Uptime (ms): \" + " +
                        "java.lang.management.ManagementFactory.getRuntimeMXBean().getUptime());}");
                byte[] byteCode = cc.toBytecode();
                cc.detach();
                return byteCode;
            } catch (Exception ex) {
                ex.printStackTrace();
            } finally {
                System.out.println(String.format("Agent - Transformation Time (ms): %d", TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - start)));
            }
        }

        return null;
    });
}
}

With this agent, the startup time is around 800ms.

How can I minimize the overhead and measure the startup time? Is there a way to directly transform a specific class without going through all classes? If I can transform a class directly, I think I should be able to minimize the overhead as much as possible.

Isuru Perera
  • 1,905
  • 1
  • 11
  • 23
  • You're asking your tool to parse and modify the target class' byte code. This is going to be expensive. That's a lot of trouble for something you can just code into your server. Why do you need to do it via bytecode manipulation? – Jim Garrison Jan 03 '18 at 06:31
  • I want to use this agent for multiple servers (and we may not be able to change the source code directly). So, that's why I thought of using the Java Agent approach. – Isuru Perera Jan 03 '18 at 06:40
  • Fair enough, but it is going to take what it takes. It just happens your tool takes longer to start up than the process you're measuring in some cases. – Jim Garrison Jan 03 '18 at 06:42
  • Yeah. I understand that there will definitely be an overhead with an agent. I just want to know whether there are ways to minimize that overhead further. – Isuru Perera Jan 03 '18 at 07:50
  • I think You can adjust You strategy here. What I can see from the code You have only advice for method exit - so You are counting everything from beginning of JVM startup. Better approach might be to have advice on method enter also in some code for Netty bootstrap and take the difference in method exit. – kaos Jan 03 '18 at 16:23

1 Answers1

2

Since you are in a premain, you likely measure the loading and initialization time for a lot of classes that have not been used before. It might be perfectly possible that a significant amount of these classes will be loaded and initialized anyway at a later time when the application uses them for the first time, without being measure as “startup time”, so having this time moved to the measured startup time might not be an actual issue.

Note that you are using lambda expressions in both variants, which causes the initialization of their backend provided by the JRE. In case of OpenJDK, it uses ASM under the hood, but since it has been repackaged to avoid conflicts with applications using ASM, it’s not the same classes Byte-Buddy is using internally, so you’re paying the price of initializing ASM twice here.

As said, if these classes will be used anyway, i.e. if the application will use lambda expressions or method references later-on, you should not worry about this, as “optimizing” it will only shift the initialization to a later time. But if the application is not using lambda expressions or method references or you want to remove this time span from the measured startup time at all costs, you may resort to an ordinary interface implementation, using an inner class or letting Agent implement the interface.

To reduce the startup time further, you may use ASM directly, skipping the initialization of the Byte-Buddy classes, e.g.

import java.lang.instrument.*;
import java.lang.management.ManagementFactory;
import java.security.ProtectionDomain;
import org.objectweb.asm.*;
import org.objectweb.asm.commons.AdviceAdapter;

public class Agent extends ClassVisitor implements ClassFileTransformer {
    private static final String NETTY_CLASS = "io/netty/bootstrap/AbstractBootstrap";

    public static void premain(String arg, Instrumentation instrumentation) {
        instrumentation.addTransformer(new Agent());
    }

    public Agent() {
        super(Opcodes.ASM5);
    }
    public byte[] transform(ClassLoader loader, String className, Class<?> cl,
                            ProtectionDomain pd, byte[] classfileBuffer) {
        if(!NETTY_CLASS.equals(className)) return null;

        ClassReader cr = new ClassReader(classfileBuffer);
        ClassWriter cw = new ClassWriter(cr, 0);
        synchronized(this) {
            super.cv = cw;
            try { cr.accept(this, 0); }
            finally { super.cv = null; }
        }
        return cw.toByteArray();
    }

    @Override
    public MethodVisitor visitMethod(
        int access, String name, String desc, String signature, String[] exceptions) {

        MethodVisitor mv = super.visitMethod(access, name, desc, signature, exceptions);
        if(name.equals("bind")
        && desc.equals("(Ljava/net/SocketAddress;)Lio/netty/channel/ChannelFuture;")) {
            return new AdviceAdapter(Opcodes.ASM5, mv, access, name, desc) {
                @Override
                protected void onMethodExit(int opcode) {
                    super.visitMethodInsn(Opcodes.INVOKESTATIC,
                        Agent.class.getName().replace('.', '/'),
                        "injectedMethod", "()V", false);
                    super.onMethodExit(opcode);
                }
            };
        }
        return mv;
    }
    public static void injectedMethod() {
        System.out.printf("Server started. Current Time (ms): %d",
                          System.currentTimeMillis());
        System.out.printf("Server started. Current Uptime (ms): %d",
                          ManagementFactory.getRuntimeMXBean().getUptime());
    }
}

(not tested)

Obviously, this code is more complicated than the code using Byte-Buddy, so you have to decide which trade-off to make.

ASM is already very lightweight. Going even deeper would imply doing the class file transformation using only a ByteBuffer and a HashMap; that’s possible, but surely not a road you want to go…

Holger
  • 285,553
  • 42
  • 434
  • 765