high-resolution timestamps for pipeline stages

[davepacheco]

Since pipeline stages tend to be logically important steps, they're a natural place to record timestamps. By having vasync record high-resolution timestamps for the start and completion of each operation in a pipeline, users can quickly understand overall pipeline latency. This behavior should be optional, since recording timestamps isn't free.

My implementation is here:
https://github.com/davepacheco/node-vasync/compare/dev-issue-29

I suggest starting with the README update to see what the interface looks like.

A few notes:

• It's tempting to record timestamps only at the start of each operation, but I want to be able to account for time spent between operations due to queueing on the event loop, so this implementation records two timestamps per operation.
• The second timestamp is recorded as a delta from the first one because I think that's how most people will want to use it. Callers that want an absolute timestamp (e.g., to construct a timeline) can always use jsprim's hrtimeAdd() function.
• I've added "start" and "elapsed" timestamps for the overall pipeline as well.
• I hope to add this interface to the other vasync functions as well, but I wanted to try it out on pipeline() first and see how it looks.

[davepacheco]

The motivator for this work is to get a better handle on Manta zone reset times. Here's example output from that pipeline:

[2016-01-07T19:02:46.713Z]  INFO: MarlinAgent/70658 on headnode: zone is now "ready" (zone=57662d27-996e-44af-8c0e-4262a0ac485a)
    stages: [
      {
        "funcname": "maZoneCleanupServer",
        "hrtimeStarted": [
          2505529,
          989110659
        ],
        "hrtimeElapsed": [
          0,
          1478110
        ]
      },
      {
        "funcname": "maZoneCleanupHyprlofs",
        "hrtimeStarted": [
          2505529,
          990644212
        ],
        "hrtimeElapsed": [
          0,
          70592875
        ]
      },
      {
        "funcname": "maZoneReadyHalt",
        "hrtimeStarted": [
          2505530,
          61307341
        ],
        "hrtimeElapsed": [
          3,
          515641159
        ]
      },
      {
        "funcname": "maZoneReadyWaitHalted",
        "hrtimeStarted": [
          2505533,
          577095951
        ],
        "hrtimeElapsed": [
          0,
          127554917
        ]
      },
      {
        "funcname": "maZoneReadyRollback",
        "hrtimeStarted": [
          2505533,
          704728785
        ],
        "hrtimeElapsed": [
          0,
          246598503
        ]
      },
      {
        "funcname": "maZoneReadyBoot",
        "hrtimeStarted": [
          2505533,
          951375954
        ],
        "hrtimeElapsed": [
          2,
          683865880
        ]
      },
      {
        "funcname": "maZoneReadyWaitBooted",
        "hrtimeStarted": [
          2505536,
          635337774
        ],
        "hrtimeElapsed": [
          5,
          7187001
        ]
      },
      {
        "funcname": "maZoneReadyKstat",
        "hrtimeStarted": [
          2505541,
          642602189
        ],
        "hrtimeElapsed": [
          0,
          27032
        ]
      },
      {
        "funcname": "maZoneReadyZsock",
        "hrtimeStarted": [
          2505541,
          642660352
        ],
        "hrtimeElapsed": [
          0,
          70053559
        ]
      },
      {
        "funcname": "maZoneReadyHyprlofs",
        "hrtimeStarted": [
          2505541,
          712752675
        ],
        "hrtimeElapsed": [
          0,
          43473758
        ]
      },
      {
        "funcname": "maZoneReadyDropAgent",
        "hrtimeStarted": [
          2505541,
          756289701
        ],
        "hrtimeElapsed": [
          0,
          184252329
        ]
      },
      {
        "funcname": "maZoneReadyStartAgent",
        "hrtimeStarted": [
          2505541,
          940581315
        ],
        "hrtimeElapsed": [
          0,
          446203179
        ]
      }
    ]
    --
    hrtimeStarted: [
      2505529,
      989105309
    ]
    --
    hrtimeElapsed: [
      12,
      397690462
    ]

[pfmooney]

It looks like a solid interface to me.

[kusor]

I like it. Adding to all the remaining vasync functions will definitely be a big win. Also, good call on making it optional.

[bahamas10]

👍 LGTM

[davepacheco]

Thanks for taking a look, everyone.

[twhiteman]

This looks good (I started looking into this myself, then found this work). I'd like to be able to start using this in Triton, for imgadm import image layer importing for example.

@davepacheco anything holding this up (well it looks like it needs a rebase, as most funcs now go through the waterfall impl), or you wanted to cover vasync.parallel first too?

If you want some help to finish this, I'd be willing to work on completing the rebase and parallel work.