Case 2: Benchmark formatting of Trackable to JSON - Nastel/gocypher-cybench-java GitHub Wiki

API

We benchmarked TNT4J framework (which is available in https://github.com/Nastel/TNT4J). TNT4J is a logging framework for tracking and tracing applications, activities, transactions, behavior and performance via a Java API. This benchmark shows how later version of TNT4J measures in terms of throughput and GC memory overhead.

Benchmark Case

TNT4J is constantly updated by adding new functions and improving new ones. In this case we will benchmark TNT4J Trackable data model conversion to JSON between TNT4J version 2.14 and TNT4J version 2.15. TNT4J has different types of messages (Activity, Event and Snapshot), which are formatted to JSON before delivery to a destination event sink. We detected high GC memory overhead in TNT4J version 2.14 during production a run and optimized it to resolve this problem in version 2.15. In this case we will benchmark both versions to verify and confirm memory optimization and throughput improvements in between versions 2.14 and 2.15.

Benchmark implementation

This benchmark implementation is based on JMH framework. Benchmark launch, results aggregation, storing and comparison is based on CyBench tools. Benchmark code is the same for both version of TNT4J. During the benchmark setup phase each of Trackable (Activity, Event, Snapshot) data model object is instantiated with properties to generate a large object size (so we will add more than 100 properties to each object). During benchmark execution phase these 3 objects are continuously converted to JSON by calling appropriate formatting functions implemented by TNT4J framework and such conversion throughput, memory, CPU are measured.

Benchmark settings:

1 JVM (Java 1.8) for benchmark execution
1 Thread, 2 iterations
TNT4J 2.14 Trackable format to JSON with memory and performance issues
TNT4J 2.15 Trackable format to JSON with updated implementation that fixed issues

See code snippet below (benchmark implementation):

import com.gocypher.cybench.core.annotation.BenchmarkMetaData;
import com.gocypher.cybench.core.annotation.BenchmarkTag;
import com.jkoolcloud.tnt4j.config.ConfigFactory;
import com.jkoolcloud.tnt4j.config.DefaultConfigFactory;
import com.jkoolcloud.tnt4j.core.OpLevel;
import com.jkoolcloud.tnt4j.core.Property;
import com.jkoolcloud.tnt4j.core.Snapshot;
import com.jkoolcloud.tnt4j.tracker.DefaultTrackerFactory;
import com.jkoolcloud.tnt4j.tracker.Tracker;
import com.jkoolcloud.tnt4j.tracker.TrackingActivity;
import com.jkoolcloud.tnt4j.tracker.TrackingEvent;
import com.jkoolcloud.tnt4j.format.JSONFormatter;

@State(Scope.Benchmark)
@BenchmarkMode(Mode.Throughput)
@OutputTimeUnit(TimeUnit.SECONDS)
@Fork(1)
@Threads(1)
@Measurement(iterations = 2, time = 5, timeUnit = TimeUnit.SECONDS)
@Warmup(iterations = 1, time = 1, timeUnit = TimeUnit.SECONDS)
public class JSONFormatterBenchmarks {

	private Snapshot snapshot ;
	private TrackingEvent event ;
	private TrackingActivity activity ;
	private  JSONFormatter formatter;
	
	
    @Setup(Level.Trial)
    public void setUp() {
    	ConfigFactory configFactory = DefaultConfigFactory.getInstance();
    	Tracker tracker = new DefaultTrackerFactory()
    	         .getInstance(configFactory.getConfig(getClass().getName()).build());
    	this.snapshot = this.createSnapshot(tracker) ;
    	this.event = this.createEvent(tracker) ;
    	this.activity = this.createActivity(tracker) ;
    	this.formatter = new JSONFormatter();
    }

    @Benchmark
    @BenchmarkTag(tag = "00a2a65f-ce96-4862-9689-1500ebed1302")
    public void formatBenchmark(Blackhole bh) {
   	 String snaphotString = this.formatter.format(this.snapshot);
   	 String eventString= this.formatter.format(this.event);
   	 String activityString = this.formatter.format(this.activity);
   	 
   	 bh.consume(snaphotString);
   	 bh.consume(eventString);
   	 bh.consume(activityString);
    }

    @TearDown(Level.Trial)
    public void cleanUp() {
    	
    }
    private Snapshot createSnapshot (Tracker tracker){
    	Snapshot snapshot = tracker.newSnapshot("Demo Snapshot for benchmarks");
    	snapshot.setCorrelator(UUID.randomUUID().toString());
    	snapshot.setTrackingId(UUID.randomUUID().toString());
    	snapshot.setTTL(150000);
    	for (int i = 0; i < 100; i++){
    		snapshot.add("sn_key"+i, "sn_value-"+i);
    	}
    	return snapshot;
    }
    private TrackingEvent createEvent (Tracker tracker){
    	TrackingEvent event  = tracker.newEvent(OpLevel.INFO, "Test Event", "123456789", "Event Message");
    	event.setCharset("UTF-8");
    	event.setCorrelator(UUID.randomUUID().toString());
    	event.setEncoding("CP1257");    
    	event.setMessage("message body for benchmarking".getBytes());
    	event.setMimeType("text/plain");
    	event.setMessageAge(15000);
    	event.setSignature("custom signature");
    	event.setTag("tnt4j");
    	event.setTrackingId(UUID.randomUUID().toString());
    	event.setTTL(150000);
    	
    	for (int i = 0; i < 100; i++){
    		event.getOperation().addProperty(new Property("event_key"+i, "event_value"+i));
    	}
    
    	return event ;
    }
    private TrackingActivity createActivity (Tracker tracker){
    	TrackingActivity activity = tracker.newActivity(OpLevel.INFO, "Test Activity");
    	activity.setCorrelator(UUID.randomUUID().toString());
    	activity.setException("Some error message.");    	
    	activity.setName("Demo activity for benchmark");
    	activity.setPID(100);
    	activity.setReasonCode(1);
    	activity.setSignature("custom signature");
    	activity.setTID(10000000L);
    	activity.setTrackingId(UUID.randomUUID().toString());
    	activity.setTTL(1500000);
    	activity.setUser("benchmarker");
    	
    	for (int i = 0; i < 100; i++){
    		activity.addProperty(new Property("activity_key"+i, "activity_value"+i));
    	}
    	return activity ;
    }
}

Benchmark results

Now let’s compare benchmark results for both TNT4J versions, see table below:

TNT4J Version	Throughput score	Units	Garbage Collector calls count	Garbage Collector time	Garbage Collector allocation rate
2.14	1,571.66	ops/s	164	106 ms	2,926.69 MB/s
2.15	3,237.58	ops/s	160	117 ms	1,859.15 MB/s

This benchmark shows that “JSON formatter” implementation yields over 2x increase in throughput and significant reduction in GC allocation rate (MB/s), confirming that version 2.15 is faster with improved GC memory footprint.

For more detailed analysis benchmarks are available in CyBench https://app.cybench.io/cybench/benchmark/view/00a2a65f-ce96-4862-9689-1500ebed1302?tagType=benchmarkTag

Conclusion

In this case we saw how code benchmarks are able to expose critical performance bottlenecks very early in the development. We used results of this benchmark to upgrade TNT4J implementation to version 2.15 for better performance and memory overhead.