Recently one of the microservices in our project behaving weirdly. Performance of that microservice gone for a toss. We thought because of business logic. One of my team members thought its due to business logic but didn’t find anything. So I sat with him and debugged the code but didn’t find anything. We know it’s slow we didn’t change any business logic recently. My experience thought me this if your assumptions didn’t help you much then its time to stop creating new assumptions and go to basics. 3 important things are happening in that microservice.
1) Reading a payload from Kafka.
2) Transforming payload to the format(structure)
which can be consumed by Druid (Our analytics tool).
3) Inserting that payload again to Kafka in the
new topic which will be consumed by Druid tranquility microservice to ingest data for our analytics
I told my team member to tell me the execution time it is taking for each task. Then callbacks & Node.js surprised us. I want to share my whole journey around this. Without wasting time Let’s start.
First, let me show you code for calculating the execution time in java. I think most of the people know this already.
My job done in 1004 ms My job done in 1001 ms Program took 2006 ms to complete
Here comes interesting part. Most of our team members came from Java background. Still, there are so many gray areas with respect to Node.js. We wrote code to calculate execution time in Java way. We wrote code like this.
Don’t Laugh. I know I am stupid. Its ok we all learn by doing mistakes. I think that’s the beauty of coding. Of course, it won’t work. Node.js works in a different fashion compared to Java. We got this unexpected output:
My job done in 1 ms My job done in 0 ms Program took 62 ms to complete Dummy CallBack Dummy CallBack
After little googling, we learned the right way. Thank you, Google!. Here we go
Now we got output which we are expecting.
Program took 2 ms to complete My job done in 1002 ms My job done in 1003 ms
In this process, we learned cool way to measuring execution time in Node.js
Output for above code:
Program: 1.307ms FunctionCall1: 1005.048ms FunctionCall2: 1006.164ms
Cool, Right? I don’t need to keep track of start time and end time, subtracting them and printing the execution time with a proper message so that at the time of reading log I wont be confused which execution time belongs to which function/business logic, Now I Just need to keep track of label that’s it. Rest Node.js will take for me/us.
Peace. Happy Coding.