High CPU Usage for Azure Table Storage on node.js

Question

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: <anonymous> 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: ~<anonymous> 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: ~<anonymous> 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: <anonymous> util.js:278
     15   34.1%        Function: formatValue util.js:189
     15  100.0%          LazyCompile: *formatProperty util.js:338
     15  100.0%            Function: <anonymous> util.js:278
     26   35.1%      LazyCompile: *formatProperty util.js:338
     26  100.0%        Function: <anonymous> 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?

Given your example, I would consider a maxed out CPU to be a good thing. Clearly, parsing is going to be most of the heavy lifting in your test. Have you tried using a bigger machine to see what happens? — Gates VP
No, my subscription is currently maxed out. I did test a .Net worker though (also just inserts) and it was able to do >500 inserts/sec with 50% cpu on an xs instance (with max bandwith). — laktak
So this is basically a pure CPU throughput test. On one side you have ".NET on Windows", on the other you have "Node.js 0.8 on Windows". It's pretty clear that .NET is going to win that fight. That stated, there may indeed be performance issues with Azure for Node. In fact, given the relative immaturity of all parts (Azure, Node, AzureForNode), it's almost certain that there is un-optimized stuff. As an early adopter though, your best bet for this stuff will be talk to guys at MS who are building this stuff. I would start with their github accounts. — Gates VP
Thanks, I've opened an issue github.com/WindowsAzure/azure-sdk-for-node/issues/633 — laktak

Gates VP Gates VP · Accepted Answer · 2013-03-05T22:35:37

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.

High CPU Usage for Azure Table Storage on node.js

1 Answers