Profiling Code Execution

Profiling different steps in a long-running function can help identify bottlenecks and optimize performance. In this post, we’ll explore how to use the Telemetry SDK to add timestamp fields and measure the execution time of various steps in a JavaScript function.

Setting Up the Project

First, let's set up a basic Node.js project and install the Telemetry SDK:

npm init -y
npm install telemetry-sh

Create an index.js file to contain our example function.

Using Telemetry to Profile Function Execution

We'll create a function that performs several tasks, and we'll use the Telemetry SDK to log the execution time of each step at the end.

// index.js
const telemetry = require('telemetry-sh');

// Initialize the Telemetry client
telemetry.init("YOUR_API_KEY");

// Function to profile steps and log them using Telemetry
const profileFunction = async () => {
  const profile = {
    start: Date.now(),
  };

  // Pre-fast DB call step
  profile.preFastDBCall = Date.now();
  await new Promise(resolve => setTimeout(resolve, 100)); // Simulate fast DB call

  // Post-fast DB call step
  profile.postFastDBCall = Date.now();

  // Pre-super slow DB call step
  profile.preSuperSlowDBCall = Date.now();
  await new Promise(resolve => setTimeout(resolve, 2000)); // Simulate super slow DB call

  // Post-super slow DB call step
  profile.postSuperSlowDBCall = Date.now();

  // Final step
  profile.end = Date.now();

  // Log the profiling data
  await telemetry.log('profile_steps', profile);

  return profile;
};

// Run the profiling function and log the profiling data
profileFunction().then(profile => {
  console.log('Profile Data:', profile);
});

Running the Example

To run the example, execute the index.js file using Node.js:

node index.js

You should see output similar to the following, showing the profile data:

Profile Data: {
  start: 1627380012345,
  preFastDBCall: 1627380012346,
  postFastDBCall: 1627380012446,
  preSuperSlowDBCall: 1627380012447,
  postSuperSlowDBCall: 1627380014447,
  end: 1627380014448
}

Analyzing the Profile Data

Next, we'll create a function to query the logged profile data from Telemetry and analyze the execution time of each step.

const queryProfileData = async (profileId) => {
  const results = await telemetry.query(`
    SELECT
      *
    FROM
      profile_steps
    WHERE
      start = ${profileId}
    ORDER BY
      timestamp
  `);

  return results;
};

const analyzeProfile = async (profileId) => {
  const profileData = await queryProfileData(profileId);

  console.log(`Pre-fast DB call to post-fast DB call: ${profileData.postFastDBCall - profileData.preFastDBCall} ms`);
  console.log(`Pre-super slow DB call to post-super slow DB call: ${profileData.postSuperSlowDBCall - profileData.preSuperSlowDBCall} ms`);
  console.log(`Total execution time: ${profileData.end - profileData.start} ms`);
};

// Run the profiling function, then query and analyze the profile data
profileFunction().then(async (profile) => {
  await analyzeProfile(profile.start);
});

This code output something similar to the following, showing the profile data and the analysis of each step's execution time:

Pre-fast DB call to post-fast DB call: 100 ms
Pre-super slow DB call to post-super slow DB call: 2000 ms
Total execution time: 2003 ms

Analysis

From the profile data analysis, you can see that:

• The fast DB call takes approximately 100 milliseconds.

• The super slow DB call takes approximately 2000 milliseconds (2 seconds).

• The total execution time for the function is around 2003 milliseconds.

This clearly indicates that the super slow DB call is a major bottleneck in the function's execution. Identifying and optimizing this step can significantly improve the overall performance of the function.

Conclusion

By integrating the Telemetry SDK, you can log and measure the execution time of various steps in your functions. This approach helps identify bottlenecks and optimize your code more effectively. Profiling with Telemetry is a powerful tool for improving performance and ensuring a better user experience.