winston-timer

Extend winston to measure time intervals

Description

An important use of logging is to measure performance of certain parts of the codebase. To make this easier, this module extends the winston logging framework for NodeJS with named timers that are started and return the high-resolution time difference when they were stopped.

Installation

npm install --save winston-timer

Usage

The module exports a single function that expects a winston logger instance and an optional configuration object.

In the simplest case (using winston as a global logger):

var winston = require('winston');
require('winston-timer')(winston);

You can also pass a stand-alone Winston.Logger object:

var winston = require('winston');
var log = new Winston.Logger(/* ... */);
require('winston-timer')(logger, {
    "use_colors": false
});

Then you can use the methods provided by the API to start and stop timers and log their results:

winston.start_log('long-running-task', 'info'); 
/* ... */
winston.stop_log('long-running-task', 'warn');

Output:

info: Starting timer 'long-running-task'
debug Finished timer 'long-running-task' in 1007.194189 ms

See test/example.js for a short example script.

API

Time difference is measured in a second-nanosecond-tuple.

To get the time difference in milliseconds, use the stop_ms method or log in milliseconds directly using stop_log method.

starting a timer that has already been started or stopping a timer that has already been stopped will cause an exception.

start(timer)

start(timer)

Starts a timer.

Arguments:

• timer [String] Required: Name of the task to time.

Returns:

• The s-ns-tuple this timer was started

stop

stop(timer)

Stops a timer.

Arguments:

• timer [String] Required: Name of the task to time.

Returns:

• The s-ns-tuple this timer was stopped.

stop_ms

stop_ms(timer)

Stops a timer and returns the time passed in milliseconds.

Arguments:

• timer [String] Required: Name of the task to time.

Returns:

• The time passed in milliseconds.

start_log

start_log(timer, level, prefix, suffix)

Starts a timer and logs a message with the timer name. By default it looks like this:

debug: Starting timer "<name of the timer>"

Arguments:

• timer [String] Required: Name of the task to time.
• level [String] Optional: The log level to use. One of silly, debug, info, warn, error. Default: config.level.
• prefix [String] Optional: String to print before the timer name. Default: config.start_prefix.
• suffix [String] Optional: String to print after the timer name. Default: config.start_suffix.

stop_log

stop_log(timer, level, prefix, suffix)

Stops a timer and logs a message with the timer name and the time elapsed in milliseconds. By default, it looks like this:

debug: Finished timer "<name of the timer>" in 1007.449218 ms

As an additional convenience, the elapsed time is highlighted according to how long it took. This behavior can be disabled by setting config.use_colors to false and the threshold times to change colors and the colors to use can be changed with the config.thresholds and config.colors arrays.

By default times will be highlighted

• < 10 ms: bold green
• < 100 ms: green
• < 500 ms: yellow
• < 1000 ms: red

• 1000 ms: bold red

Arguments:

• timer [String] Required: Name of the task to time.
• level [String] Optional: The log level to use. One of silly, debug, info, warn, error. Default: config.level.
• prefix [String] Optional: String to print before the timer name. Default: config.stop_prefix.
• suffix [String] Optional: String to print after the timer name. Default: config.stop_suffix.

Configuration

The configuration object can be passed as the second argument to the exported method to change the defaults, e.g.

require('winston-timer')(logger, {
    "level": "info",
    "use_colors": false
});

level

Logging level to use for start_log and stop_log.

Default: debug

use_colors

Whether to use colors for highlighting the elapsed time.

Default: true

thresholds

Thresholds at which to change the color highlighting of the elapsed time.

Default: [10, 100, 500, 999, Number.MAX_VALUE]

colors

Colors used for highlighting elapsed times.

See the chalk module for possible values.

Default: [chalk.green.bold, chalk.green, chalk.yellow, chalk.red, chalk.red.bold]

start_prefix

Text before the timer name.

Default: 'Starting timer "'

start_suffix

Text after the timer name.

Default: '"'

stop_prefix

Text before the timer name.

Default: 'Finished timer "'

stop_suffix

Text after the timer name.

Default: '" in '