I'm trying to figure out why my test app uses 100% when load testing Azure Table Storage inserts.

At 100% cpu I get about 230 inserts/sec on a small instance. I'm not sure if that number is OK but even then I think the cpu usage is too high.

My app basically does just this:

function insert(id)
{
  var task={ PartitionKey: id, RowKey: "1", Description: "bench bench bench" };
  pending.inc();
  var ts=azure.createTableService();
  ts.insertEntity("bench", task, function (err)
  {
    pending.dec();
    if (err) return console.log("error", err);
    reqStats.mark();
  });
}

if pending goes below 250 another 250 inserts are added (for this test no errors were logged).

I ran node with --prof but I'm not sure how to interpret the output:

Code move event for unknown code: 0x3fe5b8c0
Statistical profiling result from v8.log, (7703 ticks, 1 unaccounted, 0 excluded).

 [Unknown]:
   ticks  total  nonlib   name
      1    0.0%

 [Shared libraries]:
   ticks  total  nonlib   name
   4003   52.0%    0.0%  D:\Windows\SYSTEM32\ntdll.dll
   3347   43.5%    0.0%  F:\approot\node.exe
     47    0.6%    0.0%  D:\Windows\SYSTEM32\KERNEL32.DLL
     44    0.6%    0.0%  D:\Windows\SYSTEM32\KERNELBASE.dll
      3    0.0%    0.0%  D:\Windows\system32\mswsock.dll
      1    0.0%    0.0%  D:\Windows\SYSTEM32\WS2_32.dll

 [JavaScript]:
   ticks  total  nonlib   name
     14    0.2%    5.4%  Stub: CEntryStub
     12    0.2%    4.7%  Function: write F:\approot\node_modules\azure\node_modules\xml2js\node_modules\sax\lib\sax.js:883
     10    0.1%    3.9%  Function: EventEmitter.addListener events.js:138
      7    0.1%    2.7%  KeyedLoadIC: A keyed load IC from the snapshot
      7    0.1%    2.7%  Function: ~Request.init F:\approot\node_modules\azure\node_modules\request\main.js:108
      7    0.1%    2.7%  Function: ~ClientRequest http.js:1254
      6    0.1%    2.3%  Stub: StringAddStub
      5    0.1%    1.9%  Stub: RegExpExecStub
      5    0.1%    1.9%  LazyCompile: *urlParse url.js:92
      5    0.1%    1.9%  LazyCompile: *match native string.js:182
      5    0.1%    1.9%  Function: ~XMLFragment.toString F:\approot\node_modules\azure\node_modules\xmlbuilder\lib\XMLFragment.js:287
      4    0.1%    1.6%  LazyCompile: stringify native json.js:307
      4    0.1%    1.6%  LazyCompile: *formatProperty util.js:338
      4    0.1%    1.6%  LazyCompile: *formatPrimitive util.js:289
      4    0.1%    1.6%  LazyCompile: *EventEmitter.emit events.js:54
      4    0.1%    1.6%  Function: ~store http.js:571
      4    0.1%    1.6%  CallMegamorphic: args_count: 1
      3    0.0%    1.2%  Stub: SubStringStub
      3    0.0%    1.2%  LazyCompile: IN native runtime.js:354
      3    0.0%    1.2%  LazyCompile: APPLY_PREPARE native runtime.js:438
      3    0.0%    1.2%  LazyCompile: *GetOwnProperty native v8natives.js:637
      3    0.0%    1.2%  LazyCompile: *FromPropertyDescriptor native v8natives.js:373
      3    0.0%    1.2%  LazyCompile: *Encode native uri.js:179
      3    0.0%    1.2%  LazyCompile: *BuildResultFromMatchInfo native regexp.js:130
      3    0.0%    1.2%  Function: ~StorageServiceClient._buildRequestOptions F:\approot\node_modules\azure\lib\services\core\storageserviceclient.js:192
      3    0.0%    1.2%  Function: ~AtomHandler._writeAtomEntryValue F:\approot\node_modules\azure\lib\util\atomhandler.js:205
      3    0.0%    1.2%  Function: formatValue util.js:189
      3    0.0%    1.2%  CallMegamorphic: args_count: 3
      3    0.0%    1.2%  Builtin: A builtin from the snapshot {2}
      2    0.0%    0.8%  Stub: KeyedStoreElementStub {1}
      2    0.0%    0.8%  Stub: FastNewClosureStub
      2    0.0%    0.8%  Stub: CompareStub
      2    0.0%    0.8%  RegExp: ^"([a-zA-Z_][a-zA-Z_0-9]*)"$
      2    0.0%    0.8%  RegExp: Content-Length
      2    0.0%    0.8%  LazyCompile: join native array.js:410
      2    0.0%    0.8%  LazyCompile: ToString native runtime.js:550
      2    0.0%    0.8%  LazyCompile: ConvertToString native array.js:195
      2    0.0%    0.8%  LazyCompile: *toLowerCase native string.js:739
      2    0.0%    0.8%  LazyCompile: *socketOnData http.js:1480
      2    0.0%    0.8%  LazyCompile: *slice native string.js:510
      2    0.0%    0.8%  LazyCompile: *indexOf native string.js:118
      2    0.0%    0.8%  LazyCompile: *exports.stringStartsWith F:\approot\node_modules\azure\lib\util\util.js:131
      2    0.0%    0.8%  LazyCompile: *XMLFragment F:\approot\node_modules\azure\node_modules\xmlbuilder\lib\XMLFragment.js:8
      2    0.0%    0.8%  LazyCompile: *IsDataDescriptor native v8natives.js:354
      2    0.0%    0.8%  LazyCompile: *EventEmitter events.js:25
      2    0.0%    0.8%  Function: ~XMLFragment.element F:\approot\node_modules\azure\node_modules\xmlbuilder\lib\XMLFragment.js:18
      2    0.0%    0.8%  Function: ~Request.init F:\approot\node_modules\azure\node_modules\request\main.js:362
      2    0.0%    0.8%  Function: ~OutgoingMessage.end http.js:794
      2    0.0%    0.8%  Function: ~Logger.log F:\approot\node_modules\azure\lib\diagnostics\logger.js:68
      2    0.0%    0.8%  Builtin: A builtin from the snapshot {3}
      2    0.0%    0.8%  Builtin: A builtin from the snapshot {1}
      1    0.0%    0.4%  Stub: ToBooleanStub_String
      1    0.0%    0.4%  Stub: ToBooleanStub
      1    0.0%    0.4%  Stub: StoreArrayLiteralElementStub
      1    0.0%    0.4%  Stub: RecordWriteStub {1}
      1    0.0%    0.4%  Stub: RecordWriteStub
      1    0.0%    0.4%  Stub: NumberToStringStub
      1    0.0%    0.4%  Stub: KeyedStoreElementStub
      1    0.0%    0.4%  Stub: JSEntryStub
      1    0.0%    0.4%  Stub: InstanceofStub
      1    0.0%    0.4%  Stub: CallFunctionStub_Args0
      1    0.0%    0.4%  Stub: CallConstructStub_Recording
      1    0.0%    0.4%  Stub: CallConstructStub
      1    0.0%    0.4%  Stub: BinaryOpStub_ADD_OverwriteRight_BothStrings
      1    0.0%    0.4%  Stub: BinaryOpStub_ADD_OverwriteLeft_SMI
      1    0.0%    0.4%  Stub: BinaryOpStub_ADD_OverwriteLeft_BothStrings
      1    0.0%    0.4%  RegExp: [^A-Za-z0-9_-]
      1    0.0%    0.4%  RegExp: Date
      1    0.0%    0.4%  RegExp: (^"|"$)
      1    0.0%    0.4%  LazyCompile: toString native v8natives.js:223
      1    0.0%    0.4%  LazyCompile: Join native array.js:119
      1    0.0%    0.4%  LazyCompile: FILTER_KEY native runtime.js:398
      1    0.0%    0.4%  LazyCompile: *test native regexp.js:220
      1    0.0%    0.4%  LazyCompile: *startup.processNextTick.process.nextTick node.js:254
      1    0.0%    0.4%  LazyCompile: *startup.processNextTick.process._tickCallback node.js:233
      1    0.0%    0.4%  LazyCompile: *split native string.js:554
      1    0.0%    0.4%  LazyCompile: *replace native string.js:221
      1    0.0%    0.4%  LazyCompile: *onread net.js:377
      1    0.0%    0.4%  LazyCompile: *map native array.js:1190
      1    0.0%    0.4%  LazyCompile: *isRegExp util.js:427
      1    0.0%    0.4%  LazyCompile: *isArray native array.js:1463
      1    0.0%    0.4%  LazyCompile: *indexOf native array.js:1236
      1    0.0%    0.4%  LazyCompile: *freeParser http.js:1385
      1    0.0%    0.4%  LazyCompile: *forEach native array.js:1062
      1    0.0%    0.4%  LazyCompile: *copy F:\approot\node_modules\azure\node_modules\request\main.js:72
      1    0.0%    0.4%  LazyCompile: *afterConnect net.js:719
      1    0.0%    0.4%  LazyCompile: *insert F:\approot\server.js:1949
      1    0.0%    0.4%  LazyCompile: *UseSparseVariant native array.js:111
      1    0.0%    0.4%  LazyCompile: *TwoDigitString native date.js:213
      1    0.0%    0.4%  LazyCompile: *TableService.insertEntity F:\approot\node_modules\azure\lib\services\table\tableservice.js:500
      1    0.0%    0.4%  LazyCompile: *StringSplitOnRegExp native string.js:591
      1    0.0%    0.4%  LazyCompile: *Socket._write net.js:515
      1    0.0%    0.4%  LazyCompile: *Socket net.js:131
      1    0.0%    0.4%  LazyCompile: *ServiceClient.performRequest F:\approot\node_modules\azure\lib\services\core\serviceclient.js:161
      1    0.0%    0.4%  LazyCompile: *Request.end F:\approot\node_modules\azure\node_modules\request\main.js:952
      1    0.0%    0.4%  LazyCompile: *PropertyDescriptor native v8natives.js:482
      1    0.0%    0.4%  LazyCompile: *OutgoingMessage.write http.js:731
      1    0.0%    0.4%  LazyCompile: *CookieJar.get F:\approot\node_modules\azure\node_modules\request\vendor\cookie\jar.js:46
      1    0.0%    0.4%  LazyCompile: *AtomHandler._convertToAtomPropertyText F:\approot\node_modules\azure\lib\util\atomhandler.js:279
      1    0.0%    0.4%  LazyCompile: *Agent.addRequest http.js:1170
      1    0.0%    0.4%  LazyCompile: *$Array.configurable_ native v8natives.js:540
      1    0.0%    0.4%  Function: ~onanswer dns.js:116
      1    0.0%    0.4%  Function: ~forEach F:\approot\node_modules\lodash\dist\lodash.js:2325
      1    0.0%    0.4%  Function: ~exports.Parser.Parser.reset.saxParser.onopentag F:\approot\node_modules\azure\node_modules\xml2js\lib\xml2js.js:108
      1    0.0%    0.4%  Function: ~exports.Parser.Parser.reset.saxParser.onclosetag F:\approot\node_modules\azure\node_modules\xml2js\lib\xml2js.js:135
      1    0.0%    0.4%  Function: ~asyncCallback dns.js:65
      1    0.0%    0.4%  Function: ~WebResource.getQueryStringValues F:\approot\node_modules\azure\lib\http\webresource.js:204
      1    0.0%    0.4%  Function: ~WebResource.getQueryString F:\approot\node_modules\azure\lib\http\webresource.js:223
      1    0.0%    0.4%  Function: ~Socket.connect net.js:687
      1    0.0%    0.4%  Function: ~Socket.connect net.js:651
      1    0.0%    0.4%  Function: ~ServiceClient._performRequest.self._buildRequestOptions.requestStream.end F:\approot\node_modules\azure\lib\services\core\serviceclient.js:239
      1    0.0%    0.4%  Function: ~ServiceClient._performRequest.self._buildRequestOptions.operation F:\approot\node_modules\azure\lib\services\core\serviceclient.js:216
      1    0.0%    0.4%  Function: ~Request.write F:\approot\node_modules\azure\node_modules\request\main.js:948
      1    0.0%    0.4%  Function: ~Request.start.self.req.self.httpModule.request.response.on.self._ended F:\approot\node_modules\azure\node_modules\request\main.js:617
      1    0.0%    0.4%  Function: ~Request F:\approot\node_modules\azure\node_modules\request\main.js:84
      1    0.0%    0.4%  Function: ~EventEmitter.addListener events.js:138
      1    0.0%    0.4%  Function: ~AtomHandler.serialize F:\approot\node_modules\azure\lib\util\atomhandler.js:174
      1    0.0%    0.4%  CallNormal: args_count: 0
      1    0.0%    0.4%  CallMegamorphic: args_count: 2
      1    0.0%    0.4%  Builtin: A builtin from the snapshot {5}
      1    0.0%    0.4%  Builtin: A builtin from the snapshot {4}
      1    0.0%    0.4%  Builtin: A builtin from the snapshot

 [C++]:
   ticks  total  nonlib   name

 [GC]:
   ticks  total  nonlib   name
    268    3.5%

 [Bottom up (heavy) profile]:
  Note: percentage shows a share of a particular caller in the total
  amount of its parent calls.
  Callers occupying less than 2.0% are not shown.

   ticks parent  name
   4003   52.0%  D:\Windows\SYSTEM32\ntdll.dll
     97    2.4%    LazyCompile: *connect net.js:614
     97  100.0%      Function: ~Socket.connect net.js:687
     97  100.0%        Function: ~asyncCallback dns.js:65
     97  100.0%          Function: ~onanswer dns.js:116

   3347   43.5%  F:\approot\node.exe
    533   15.9%    Function: exports.Parser.Parser.parseString F:\approot\node_modules\azure\node_modules\xml2js\lib\xml2js.js:205
    533  100.0%      Function: ~__bind F:\approot\node_modules\azure\node_modules\xml2js\lib\xml2js.js:6
    533  100.0%        Function: ServiceClient._parseResponse F:\approot\node_modules\azure\lib\services\core\serviceclient.js:499
    516   96.8%          LazyCompile: *ServiceClient._processResponse F:\approot\node_modules\azure\lib\services\core\serviceclient.js:307
    516  100.0%            Function: ~ServiceClient._performRequest.self._buildRequestOptions.processResponseCallback F:\approot\node_modules\azure\lib\services\core\serviceclient.js:219
     17    3.2%          Function: ~ServiceClient._processResponse F:\approot\node_modules\azure\lib\services\core\serviceclient.js:307
     17  100.0%            Function: ~ServiceClient._performRequest.self._buildRequestOptions.processResponseCallback F:\approot\node_modules\azure\lib\services\core\serviceclient.js:219
    258    7.7%    LazyCompile: *socketOnData http.js:1480
    172   66.7%      LazyCompile: *onread net.js:377
      7    2.7%      Function: ~onread net.js:377
    196    5.9%    LazyCompile: *is F:\approot\node_modules\azure\node_modules\xml2js\node_modules\sax\lib\sax.js:275
    196  100.0%      Function: write F:\approot\node_modules\azure\node_modules\xml2js\node_modules\sax\lib\sax.js:883
    196  100.0%        Function: exports.Parser.Parser.parseString F:\approot\node_modules\azure\node_modules\xml2js\lib\xml2js.js:205
    196  100.0%          Function: ~__bind F:\approot\node_modules\azure\node_modules\xml2js\lib\xml2js.js:6
    196  100.0%            Function: ServiceClient._parseResponse F:\approot\node_modules\azure\lib\services\core\serviceclient.js:499
    161    4.8%    Function: write F:\approot\node_modules\azure\node_modules\xml2js\node_modules\sax\lib\sax.js:883
    161  100.0%      Function: exports.Parser.Parser.parseString F:\approot\node_modules\azure\node_modules\xml2js\lib\xml2js.js:205
    161  100.0%        Function: ~__bind F:\approot\node_modules\azure\node_modules\xml2js\lib\xml2js.js:6
    161  100.0%          Function: ServiceClient._parseResponse F:\approot\node_modules\azure\lib\services\core\serviceclient.js:499
    156   96.9%            LazyCompile: *ServiceClient._processResponse F:\approot\node_modules\azure\lib\services\core\serviceclient.js:307
      5    3.1%            Function: ~ServiceClient._processResponse F:\approot\node_modules\azure\lib\services\core\serviceclient.js:307
     90    2.7%    Function: ~ClientRequest.onSocket http.js:1617
     86   95.6%      LazyCompile: *startup.processNextTick.process._tickCallback node.js:233
      4    4.4%      Function: ~startup.processNextTick.process._tickCallback node.js:233
     85    2.5%    LazyCompile: *EventEmitter.emit events.js:54
     29   34.1%      Function:  F:\approot\node_modules\azure\node_modules\request\main.js:636
     29  100.0%        LazyCompile: *EventEmitter.emit events.js:54
     29  100.0%          Function: ~Request.start.self.req.self.httpModule.request.buffer F:\approot\node_modules\azure\node_modules\request\main.js:621
     29  100.0%            LazyCompile: *EventEmitter.emit events.js:54
     23   27.1%      Function: ~Socket._destroy.destroyed net.js:357
     23  100.0%        LazyCompile: *startup.processNextTick.process._tickCallback node.js:233
     17   20.0%      Function: EventEmitter.addListener events.js:138
      7   41.2%        Function: ~ F:\approot\node_modules\azure\node_modules\request\main.js:519
      7  100.0%          Function: ~g events.js:190
      7  100.0%            LazyCompile: *EventEmitter.emit events.js:54
      5   29.4%        Function: ~Request.start F:\approot\node_modules\azure\node_modules\request\main.js:503
      5  100.0%          Function: ~Request.write F:\approot\node_modules\azure\node_modules\request\main.js:948
      5  100.0%            Function: ~Request.init F:\approot\node_modules\azure\node_modules\request\main.js:362
      2   11.8%        LazyCompile: *Agent.createSocket http.js:1189
      2  100.0%          LazyCompile: *Agent.addRequest http.js:1170
      2  100.0%            Function: ~ClientRequest http.js:1254
      1    5.9%        LazyCompile: *parserOnIncomingClient http.js:1531
      1  100.0%          LazyCompile: *socketOnData http.js:1480
      1    5.9%        LazyCompile: *EventEmitter.once events.js:184
      1  100.0%          Function: ~ F:\approot\node_modules\azure\node_modules\request\main.js:519
      1  100.0%            Function: ~g events.js:190
      1    5.9%        Function: ~Request.init F:\approot\node_modules\azure\node_modules\request\main.js:108
      1  100.0%          Function: ~Request F:\approot\node_modules\azure\node_modules\request\main.js:84
      1  100.0%            LazyCompile: *request F:\approot\node_modules\azure\node_modules\request\main.js:983
      4    4.7%      LazyCompile: *parserOnMessageComplete http.js:127
      4  100.0%        LazyCompile: *socketOnData http.js:1480
      3   75.0%          LazyCompile: *onread net.js:377
      3    3.5%      LazyCompile: *responseOnEnd http.js:1591
      3  100.0%        LazyCompile: *EventEmitter.emit events.js:54
      2   66.7%          LazyCompile: *IncomingMessage._emitEnd http.js:364
      2  100.0%            Function: ~parserOnMessageComplete http.js:127
      1   33.3%          LazyCompile: *parserOnMessageComplete http.js:127
      1  100.0%            LazyCompile: *socketOnData http.js:1480
      2    2.4%      Function: ~Request.start.self.req.self.httpModule.request.buffer F:\approot\node_modules\azure\node_modules\request\main.js:621
      2  100.0%        LazyCompile: *EventEmitter.emit events.js:54
      1   50.0%          Function: ~parserOnMessageComplete http.js:127
      1  100.0%            LazyCompile: *socketOnData http.js:1480
      1   50.0%          Function: ~IncomingMessage._emitEnd http.js:364
      1  100.0%            Function: ~parserOnMessageComplete http.js:127
      2    2.4%      Function: ~Agent.createSocket.onFree http.js:1209
      2  100.0%        LazyCompile: *EventEmitter.emit events.js:54
      2  100.0%          LazyCompile: *responseOnEnd http.js:1591
      2  100.0%            LazyCompile: *EventEmitter.emit events.js:54
     74    2.2%    LazyCompile: *replace native string.js:221
     44   59.5%      LazyCompile: *formatPrimitive util.js:289
     29   65.9%        LazyCompile: *formatValue util.js:189
     29  100.0%          LazyCompile: *formatProperty util.js:338
     29  100.0%            Function:  util.js:278
     15   34.1%        Function: formatValue util.js:189
     15  100.0%          LazyCompile: *formatProperty util.js:338
     15  100.0%            Function:  util.js:278
     26   35.1%      LazyCompile: *formatProperty util.js:338
     26  100.0%        Function:  util.js:278
     26  100.0%          LazyCompile: *map native array.js:1190
     16   61.5%            LazyCompile: *formatValue util.js:189
     10   38.5%            Function: formatValue util.js:189
      3    4.1%      LazyCompile: *Agent.createSocket http.js:1189
      3  100.0%        LazyCompile: *Agent.addRequest http.js:1170
      3  100.0%          Function: ~ClientRequest http.js:1254
      3  100.0%            Function: ~exports.request http.js:1718

Apparently a lot of time is spent in exports.Parser.Parser.parseString (right?) - but why is that Function only listed in the bottom-up table?

Why was half the time spent in ntdll?

Is this an issue with the azure-sdk-for-node, with node.js itself or are my expectations just too high?

I will fill in a basic answer here.

It looks like all your CPU work is at the network level & in serializing XML to/from JSON. In the comments you mention getting 2-4x better performance out of .NET.

Is this an issue with the azure-sdk-for-node, with node.js itself or are my expectations just too high?

I think the answer to both parts is yes.

In something purely CPU-bound, .NET on Windows is going to beat Node.JS on Windows. Not really a contest here.

That stated, it's also quite probable that there are some performance bottlenecks in both azure-sdk-for-node and within Node.JS itself. Most of this stuff has been around for less than a year and node.js is primarily being run & tuned for Linux not Windows.

I strongly recommend testing the same thing on a Linux box (you can host these in Azure) to see if you get better performance. I also recommend sharing your stuff with the team @ MS that handles Node.