Using 'gnomon' to Analyze Console Outputs (with examples)

Gnomon is a versatile utility that allows users to enhance console logging by adding timestamps. It is particularly useful for developers who want to pinpoint slow processes or examine the time taken by various commands. By annotating console outputs with different types of time-related data, such as elapsed time and absolute timestamp, gnomon helps in performance monitoring and debugging. More so, it allows color-coded thresholds to easily identify processes that take longer than expected.

Use case 1: Piping stdout through gnomon

Code:

npm test | gnomon

Motivation:

By using a simple pipe with gnomon, developers can gain insights into the runtime behavior of their npm test suite. Often during testing, developers are interested in knowing which tests or processes take longer. Piping output through gnomon gives real-time timestamped annotations, making it easier to detect and address performance bottlenecks or latency issues in the test execution.

Explanation:

• npm test: This command runs the test suite specified in the project’s package.json.
• |: This operator pipes the standard output (stdout) of the preceding command into the next command.
• gnomon: This utility adds timestamps to each line of the output from the previous command, thereby enriching the data with temporal context.

Example output:

0.0024 My test case started
0.1240 My test case completed

Use case 2: Show number of seconds since the start of the process

Code:

npm test | gnomon --type=elapsed-total

Motivation:

Tracking the total elapsed time since the beginning of a process can be essential for understanding the overall performance and efficiency of run scripts or tasks. By utilizing a cumulative elapsed timer, developers can optimize processes, ensure they meet performance requirements, and assess the impact of recent changes.

Explanation:

• --type=elapsed-total: This flag directs gnomon to show the total elapsed time from when the command started, rather than just the time elapsed since the last line of output, which offers a clearer picture of duration throughout the process execution.

Example output:

0.0024 Total elapsed time: 0.01 seconds
1.0024 Total elapsed time: 1.00 seconds

Use case 3: Show an absolute timestamp in UTC

Code:

npm test | gnomon --type=absolute

Motivation:

Absolute timestamps are crucial for logging events in distributed systems where synchronizing logs from different systems is necessary. Absolute UTC timestamps provide an accurate and standardized time reference that can aid in diagnosing issues across systems and understanding chronological order in a global context.

Explanation:

• --type=absolute: This option sets gnomon to display timestamps in UTC at the moment each line of output is generated, enabling precise timekeeping for audit and monitoring purposes.

Example output:

2023-10-10T10:20:44.024Z My test case started
2023-10-10T10:20:45.124Z My test case completed

Use case 4: Use a high threshold of 0.5 seconds, with timestamps colored bright red

Code:

npm test | gnomon --high 0.5

Motivation:

In projects with performance benchmarks, it’s important to quickly identify processes exceeding expected durations. By coloring timestamps red when they exceed 0.5 seconds, gnomon provides visual cues, aiding developers to easily spot and investigate potential performance issues that require immediate attention.

Explanation:

• --high 0.5: This parameter sets a threshold of 0.5 seconds. If any step in the process takes longer than this, the timestamp will appear in bright red, offering an impactful visual alert to signal that a specific part requires further investigation.

Example output:

0.0024 My test case started
5.5011 My long-running test case completed (timestamp in bright red)

Use case 5: Use a medium threshold of 0.2 seconds, with timestamps colored bright yellow

Code:

npm test | gnomon --medium 0.2

Motivation:

For applications requiring tighter performance constraints, detecting operations exceeding medium thresholds is crucial for maintaining optimal performance. The bright yellow color coding serves as a proactive warning system, indicating processes that, while not critical, still warrant further inspection for optimization opportunities.

Explanation:

• --medium 0.2: This option highlights timestamps in bright yellow if they exceed 0.2 seconds, emphasizing those operations that fall into a ‘cautionary’ zone needing potential performance refinement but are not as urgent as those crossing the high threshold.

Example output:

0.0024 My test case started
0.3004 My slightly slow test case completed (timestamp in bright yellow)

Conclusion:

Gnomon is an invaluable tool in the developer’s toolkit for enhancing console logging with timestamps. It aids in identifying performance bottlenecks and understanding the time-related dynamics of command executions. Whether through simple stdout piping, tracking elapsed time, setting visual thresholds, or using absolute UTC timestamps, gnomon empowers developers with the insights needed to troubleshoot and optimize processes effectively.