• Stars
    star
    264
  • Rank 155,103 (Top 4 %)
  • Language
    CoffeeScript
  • Created over 10 years ago
  • Updated about 10 years ago

Reviews

There are no reviews yet. Be the first to send feedback to the community and the maintainers!

Repository Details

Asynchronous CPU profiling for node

Node async-profile profiles CPU usage in node apps.

It lets you see at a glance how much CPU time is being taken up by a given part of your app, even if that part of your app is also doing asynchronous IO.

I built it at Bugsnag to help us understand why our background processors were using 100% CPU all the time.

Installation

This currently only works on node 0.10. 0.11 support should be easy to add, and much lower overhead :).

npm install async-profile

Usage

Call AsyncProfile.profile with a function. That function will be called asynchronously, and all of the timeouts and network events it causes will also be profiled. A summary will then be printed.

var AsyncProfile = require('async-profile')

AsyncProfile.profile(function () {

    // doStuff
    setTimeout(function () {
        // doAsyncStuff
    });

});

For more options see the advanced usage section

Interpreting the output

The output looks something like this: (taken from a profile of bugsnag's backend)

total: 1.823ms (in 2.213ms real time, CPU load: 0.8, wait time: 3.688ms)
0.879: 0.011ms    at Function.Project.fromCache (/0/bugsnag/event-worker/lib/project.coffee:12:16) (0.072ms)
0.970: 0.363ms    [no mark] (0.250ms)
1.589: 0.002ms        at /0/bugsnag/event-worker/workers/notify.coffee:29:13 (0.000ms)
1.622: 0.010ms        at /0/bugsnag/event-worker/workers/notify.coffee:30:13 (0.000ms)
1.668: 0.043ms        at Event.hash (/0/bugsnag/event-worker/lib/event/event.coffee:238:16) (0.061ms)
1.780: 0.064ms          at /0/bugsnag/event-worker/lib/event/event.coffee:246:21 (0.098ms)
2.016: 0.064ms            at Object.exports.count (/0/bugsnag/event-worker/lib/throttling.coffee:12:14) (0.122ms)
2.250: 0.052ms            REDIS EVAL SCRIPT (0.123)
2.506: 0.166ms                at throttleProjectEvent (/0/bugsnag/event-worker/lib/throttling.coffee:125:14) (0.295ms)
2.433: 0.002ms                at throttleProjectEvent (/0/bugsnag/event-worker/lib/throttling.coffee:125:14) (0.000ms)
2.211: 0.002ms              at throttleAccountEvent (/0/bugsnag/event-worker/lib/throttling.coffee:73:14) (0.000ms)
1.947: 0.002ms            at Object.exports.count (/0/bugsnag/event-worker/lib/throttling.coffee:12:14) (0.000ms)
1.593: 0.001ms        at Event.hash (/0/bugsnag/event-worker/lib/event/event.coffee:238:16) (0.000ms)
0.775: 0.003ms    at Function.Project.fromCache (/0/bugsnag/event-worker/lib/project.coffee:12:16) (0.000ms)

The first line contains 4 numbers:

  • total — the total amount of time spent running CPU.
  • real time — the amount of time between the first callack starting and the last callback ending.
  • CPU load — is just total / real time. As node is singlethreaded, this number ranges between 0 (CPU wasn't doing anything) and 1 (CPU was running the whole time).
  • wait time — the sum of the times between each callback being created and being called. High wait times can happen either because you're waiting for a lot of parallel IO events, or because you're waiting for other callbacks to stop using the CPU.

Each subsequent line contains 4 bits of information:

  • start: The time since you called new AsyncProfile() and when this callback started running.
  • cpu time: The amount of CPU time it took to execute this callback.
  • location: The point in your code at which this callback was created. (see also marking).
  • overhead: The amount of CPU time it took to calculate location (see also speed) which has been subtraced from the cpu time column.

Additionally the indentation lets you re-construct the tree of callbacks.

Marking

Sometimes it's hard to figure out exactly what's running when, particularly as the point at which the underlying async callback is created might not correspond to the location of a callback function in your code. At any point while the profiler is running you can mark the current callback to make it easy to spot in the profiler output.

AsyncProfile.mark 'SOMETHING EASY TO SPOT'

For example in the above output, I've done that for the callback that was running redis.eval and marked it as 'REDIS EVAL SCRIPT'.

Advanced

If you need advanced behaviour, you need to create the profiler manually, and then run some code. The profiler will be active for any callbacks created synchronously after it was.

setTimeout(function () {
    p = new AsyncProfiler();

    setTimeout(function () {
        // doStuff

    });
});

Speed

Like all profilers, this one comes with some overhead. In fact, by default it has so much overhead that I had to calculate it and then subtract it from the results :p.

There is some overhead not included in the overhead numbers, but it should hopefully be fairly insignficant (1-10μs or so per async call) and also not included in the profiler output.

You can make the profiler faster by creating it with the fast option. This disables both stack-trace calculation, and overhead calculation.

new AsyncProfile({fast: true})

Stopping

also known as "help, it's not displaying anything"

If your process happens to make an infinite cascade of callbacks (often this happens with promises libraries), then you will have to manually stop the profiler manually. For example using a promise you might want to do something like:

var p = new AsyncProfile()
Promise.try(doWork).finally(function () {
    p.stop();
});

Custom reports

You can pass a callback into the constructor to generate your own output. The default callback looks like this:

new AsyncProfile({
    callback: function (result) {
        result.print();
    }
);

The result object looks like this:

{
    start: [1, 000000000], # process.hrtime()
    end:   [9, 000000000], # process.hrtime()
    ticks: [
        {
            queue: [1, 000000000], # when the callback was created
            start: [2, 000000000], # when the callback was called
            end:   [3, 000000000], # when the callback finished
            overhead: [0, 000100000], # how much time was spent inside the profiler itself
            parent: { ... }, # the tick that was running when the callback was created
        }
    ]
}

This gives you a flattened tree of ticks, sorted by queue time. The parent will always come before its children in the array.

Common problems

No output is produced

Try manually stopping the profiler. You might have an infinite chain of callbacks, or no callbacks at all.

Some callbacks are missing

We're using async-listener under the hood, and it sometimes can't "see" beyond some libraries (like redis or mongo) that use connection queues.

The solution is to manually create a bridge over the asynchronous call. You can look at the code to see how I did it for mongo and redis. Pull requests are welcome.

Crashes on require with async-listener polyfill warning.

Either you're using node 0.11 (congrats!) or you're including async-listener from multiple places.

You can fix this by sending a pull request :).

Meta-fu

async-profile is licensed under the MIT license. Comments, pull-requests and issue reports are welcome.

More Repositories

1

pry-rescue

Start a pry session whenever something goes wrong.
Ruby
850
star
2

showterm

The rubygem to upload to http://showterm.io
Ruby
600
star
3

aws-name-server

DNS server that lets you look up ec2 instances by instance name
Go
560
star
4

vim-bracketed-paste

Handles bracketed-paste-mode in vim (aka. automatic `:set paste`)
Vim Script
481
star
5

showterm.io

The website for showterm!
JavaScript
354
star
6

dotgpg

A secure and easy-to-use store for your production secrets
Ruby
162
star
7

jist

Jist just gists
Ruby
160
star
8

git-aliae

Random git stuff....
Shell
81
star
9

console.log

Log to the Javascript console from ruby.
Ruby
79
star
10

font

golang parser for OpenType files.
Go
70
star
11

em-imap

An event machine based IMAP client
Ruby
69
star
12

lspace

Safe operation-local global variables!
Ruby
62
star
13

pry-debundle

Allows you to use gems not in your Gemfile from Pry.
Ruby
50
star
14

gpg-decoder

A port of the awesome ASN.1 Javascript Decoder for GPG messages
JavaScript
44
star
15

ruby-source_map

A Ruby library for interacting with the awesome javascript SourceMaps.
Ruby
40
star
16

trie-ing

The fastest weighted auto-completion trie known to...
JavaScript
33
star
17

unicode-dragon

Eats invalid unicode for breakfast.
JavaScript
25
star
18

interception

Listen to raise in ruby
Ruby
24
star
19

twitter-followers

A tool to download all a user's twitter followers
Go
22
star
20

http_load

hard-core HTTP load tester from http://acme.com/software/http_load/
C
20
star
21

pry-syntax-hacks

Some syntactic "high fructose corn syrup"s for pry.
Ruby
16
star
22

zepto-ghostclick

A Zepto plugin to help avoid ghost clicks
JavaScript
14
star
23

rfc2047-ruby

An RFC 2047 compliant email header parser
Ruby
11
star
24

motion-rubygems

Very very broken support for rubygems in RubyMotion
Ruby
11
star
25

pry-highlight

Highlights strings in pry output
Ruby
9
star
26

cap-runit

Capistrano 3 runit support
Ruby
9
star
27

gotar

A replacement for `go build` that includes static assets
Go
9
star
28

cause

A backport of Exception#cause from Ruby-2.1.0
Ruby
9
star
29

golo

defer go compile errors to runtime
Go
8
star
30

pry-em

Playing with async stuff is as easy as pry!
Ruby
8
star
31

ruby18_source_location

Giving Ruby 1.8.7 a chance to join in the #source_location fun.
Ruby
8
star
32

conradirwin.github.com

My Blog.
HTML
6
star
33

mongoid-rails

Strong parameters integration with mongoid
Ruby
6
star
34

yada_yada

A reimplementation of perl's Yada Yada operator in ruby!
Ruby
6
star
35

pry-capture

The old version of pry-rescue!
Ruby
5
star
36

encoding-codepage

A rubygem that lets you look up encodings by Microsoft® Code Page Identifier
Ruby
5
star
37

thin-attach_socket

Adds Thin::Backend::AttachSocket for running thin behind einhorn
Ruby
4
star
38

vim-comment-object

Perform actions on an entire comment.
Vim Script
4
star
39

wiktionary

A python library for playing with Wiktionary
Python
4
star
40

go-dwarf

DWARF debugging data parser in go
Go
4
star
41

self

Provides debug-access to private methods and instance variables of ruby Objects
Ruby
4
star
42

optimistic_dev

An optimistic developer twitter persona!
Go
4
star
43

secure_equals

Constant time equality for ruby.
Ruby
4
star
44

canvas-animation-loader

GPU-accelerated canvas animations in webpack
JavaScript
3
star
45

rbenv-all

Provides "rbenv all" for running one command against all your rubies
Shell
3
star
46

p_enwikt

git fork of https://fisheye.toolserver.org/browse/enwikt/
Perl
3
star
47

git-fetch-series

A tool to let you download patches from the git mailing list.
Python
3
star
48

c_location

source_location for methods written in C (Method#c_location)
Ruby
3
star
49

autoconfig.mozillamessaging.com

Mirror of http://svn.mozilla.org/mozillamessaging.com/sites/autoconfig.mozillamessaging.com, Mozilla's ISPDB
DIGITAL Command Language
3
star
50

pry-lexer

A pygments lexer for pry sessions!
Python
3
star
51

proxies

Ruby
2
star
52

jslint-node

Run jslint with node
JavaScript
2
star
53

mruby-example

"Hello world!" executable with mruby
Ruby
2
star
54

bisect

Library for maintaining sorted Arrays borrowed from Python
Ruby
2
star
55

go-for-rubyists

Go for rubyists, a tech talk.
JavaScript
2
star
56

amfs

Go
2
star
57

fireplace

Go
2
star
58

howtobuilda.bike

A writeup of building a bike
CSS
2
star
59

Commune

Ruby
2
star
60

libxml2

My fork of git://git.gnome.org/libxml2
C
2
star
61

motion-rubygems-example

An example project that uses motion-rubygems
Ruby
2
star
62

better-gmail

clean up gmail interface
JavaScript
1
star
63

node-zset

Disk backed semi-sorted sets
CoffeeScript
1
star
64

test

1
star
65

bytes

A small utility for dealing with raw bytes
Go
1
star
66

cap3-elb

Capistrano commands for managing your ELB.
Ruby
1
star
67

qrcode-raplet

A raplet to make it easier to phone people
JavaScript
1
star
68

udt

Ideas for CRDTs
Go
1
star
69

mrsa

Mediated RSA in golang
Go
1
star
70

em-monitor

For monitoring the distribution of CPU-spans in your event machine reactor thread.
Ruby
1
star
71

parallel

Structured concurrency for go
Go
1
star
72

browser-action-open

JavaScript
1
star
73

plotocrat

Automatically plot probability distributions
JavaScript
1
star
74

code-point-mapping

Map between javascript string indices and unicode code point offsets effectively
TypeScript
1
star
75

ggg

An experimental self-hosted debugger for go
Go
1
star
76

music

LilyPond
1
star
77

source_map-jsmin

A Source Map enabled pure-ruby version of Doug Crockford's awesome jsmin
JavaScript
1
star
78

goer

Some people like to browse, other's prefer to go directly.
JavaScript
1
star
79

introducing-teacup

The really simple sample app created in http://cirw.in/blog/introducing-teacup
Ruby
1
star
80

beamer-bootstrap

A bootstrap for beamer presentations that include code and images.
C
1
star
81

airpad

An iPad client for the awesome http://airbrake.io/
Objective-C
1
star
82

tracing-bug

Rust
1
star
83

lxterminal-clicky

A terminal emulator you can click on
C
1
star