This repository has been archived by the owner. It is now read-only.

zero byte writes #3349

Closed
brendangregg opened this Issue May 31, 2012 · 2 comments

Comments

Projects
None yet
2 participants

Servers can be written in a way that accidentally calls zero byte write() syscalls. While these are fast, they are also unnecessary, and cause a small degree of performance overhead.

One way to fix these may be to modify net.js, and add a test for data.length. eg:

Socket.prototype.write = function(data, arg1, arg2) {
  var encoding, cb;

  if (data.length === 0)
          return;

...

Details

this was noticed during a micro-benchmark on node v0.6.17. This dtrace one-liner shows the requested size of write() syscalls:

# dtrace -n 'syscall::write:entry /execname == "node"/ { @[arg2] = count(); }'
dtrace: description 'syscall::write:entry ' matched 1 probe
^C
[...]
               81                9
              136                9
               87           213803
               88           213803
                0           213805

The 87 and 88 byte writes were for the header and contents. The 0 byte write contains nothing.

Here is a stack trace for one of those 0 byte writes:

# dtrace -n 'syscall::write:entry /execname == "node" && arg2 == 0/ { @[jstack(100, 8000)] = count(); }'
^C
[...]
              libc.so.1`__write+0x15
              node`uv__write+0x1d2
              node`uv_write2+0x284
              node`uv_write+0x1f
              node`_ZN4node10StreamWrap5WriteERKN2v89ArgumentsE+0x1a2
              << internal code >>
              (anon) as Socket._write at net.js position 22544
              (anon) as Socket.write at net.js position 20696
              << adaptor >>
              (anon) as OutgoingMessage._send at http.js position 20254
              << adaptor >>
              (anon) as OutgoingMessage.end at http.js position 34882
              << adaptor >>
              (anon) as (anon) at /root/nodejs-cluster-fixed-localnet.js position 1222
              (anon) as EventEmitter.emit at events.js position 3532
              << adaptor >>
              (anon) as parser.onIncoming at http.js position 85466
              parserOnHeadersComplete at http.js position 3972
              << internal >>
              << entry >>
              node`_ZN2v88internalL6InvokeEbNS0_6HandleINS0_10JSFunctionEEENS1_INS0_6ObjectEEEiPPPS4_Pb+0x1d5
              node`_ZN2v88internal9Execution4CallENS0_6HandleINS0_6ObjectEEES4_iPPPS3_Pbb+0x57
              node`_ZN2v88Function4CallENS_6HandleINS_6ObjectEEEiPNS1_INS_5ValueEEE+0xd5
              node`_ZN4node6Parser19on_headers_completeEP11http_parser+0x423
              node`http_parser_execute+0xaab
              node`_ZN4node6Parser7ExecuteERKN2v89ArgumentsE+0x327
              << internal code >>
              (anon) as socket.ondata at http.js position 82434
              onread at net.js position 16538
              << internal >>
              << entry >>
              node`_ZN2v88internalL6InvokeEbNS0_6HandleINS0_10JSFunctionEEENS1_INS0_6ObjectEEEiPPPS4_Pb+0x1d5
              node`_ZN2v88internal9Execution4CallENS0_6HandleINS0_6ObjectEEES4_iPPPS3_Pbb+0x57
              node`_ZN2v88Function4CallENS_6HandleINS_6ObjectEEEiPNS1_INS_5ValueEEE+0xd5
              node`_ZN4node12MakeCallbackEN2v86HandleINS0_6ObjectEEEPKciPNS1_INS0_5ValueEEE+0xc7
              node`_ZN4node10StreamWrap12OnReadCommonEP11uv_stream_si8uv_buf_t14uv_handle_type+0x10d
              node`_ZN4node10StreamWrap6OnReadEP11uv_stream_si8uv_buf_t+0x2e
              node`uv__read+0x350
              node`uv__stream_io+0x11b
              node`ev_invoke_pending+0x71
              node`ev_run+0x452
              node`uv_run+0x17
              node`_ZN4node5StartEiPPc+0xa6
              node`main+0x1b
              node`_start+0x83

The following are three simple servers, along with their syscall behavior as analyzed using truss.

test-server1.js

var http = require('http');
http.createServer(function (req, res) {
        res.writeHead(200, {'Content-Type': 'text/plain'});
        res.end('G\'Day\n');
}).listen(8080, "0.0.0.0");
# truss -wall -ftwrite node test-server1.js 
81195/1:        write(7, 0x085C0F20, 113)                       = 113
81195/1:           H T T P / 1 . 1   2 0 0   O K\r\n C o n t e n t - T y p e :   t
81195/1:           e x t / p l a i n\r\n C o n n e c t i o n :   k e e p - a l i v
81195/1:           e\r\n T r a n s f e r - E n c o d i n g :   c h u n k e d\r\n\r
81195/1:          \n 6\r\n G ' D a y\n\r\n 0\r\n\r\n

truss shows that the server responded with a single write(). I think this is the expected behavior based on the documentation.

test-server2.js

Now, performing an explicit response.write(), and an empty response.end():

var http = require('http');
http.createServer(function (req, res) {
        res.writeHead(200, {'Content-Type': 'text/plain'});
        res.write('G\'Day\n');
        res.end();
}).listen(8080, "0.0.0.0");

The documentation for response.end() reads: "If data is specified, it is equivalent to calling response.write(data, encoding) followed by response.end()." Which suggests that the above change makes no difference.

# truss -wall -ftwrite node test-server2.js 
82347/1:        write(7, 0x085C0F20, 108)                       = 108
82347/1:           H T T P / 1 . 1   2 0 0   O K\r\n C o n t e n t - T y p e :   t
82347/1:           e x t / p l a i n\r\n C o n n e c t i o n :   k e e p - a l i v
82347/1:           e\r\n T r a n s f e r - E n c o d i n g :   c h u n k e d\r\n\r
82347/1:          \n 6\r\n G ' D a y\n\r\n
82347/1:        write(7, " 0\r\n\r\n", 5)                       = 5

Now two write()s are called, the second repeating the \r\n\r\n sequence.

test-server3.js

Now, adding a content-length (which replicates what the original micro-benchmark tested):

var http = require('http');
http.createServer(function (req, res) {
        res.writeHead(200, {'Content-Type': 'text/plain', 'Content-Length': 6});
        res.write('G\'Day\n');
        res.end();
}).listen(8080, "0.0.0.0");
# truss -wall -ftwrite node test-server3.js 
85943/1:        write(7, 0x085C0F20, 94)                        = 94
85943/1:           H T T P / 1 . 1   2 0 0   O K\r\n C o n t e n t - T y p e :   t
85943/1:           e x t / p l a i n\r\n C o n t e n t - L e n g t h :   6\r\n C o
85943/1:           n n e c t i o n :   k e e p - a l i v e\r\n\r\n G ' D a y\n
85943/1:        write(7, 0x085C0F7E, 0)                         = 0

Zero byte write.

Member

bnoordhuis commented May 31, 2012

Thorough writeup. Nice, thanks.

I fixed the zero write after an empty response.end() (or after an empty anything really) in 9ae6d8f but that commit only exists in master.

truss shows that the server responded with a single write(). I think this is the expected behavior based on the documentation.

Yes. We try hard to fit everything into a single packet.

Sorry, I should have checked master; thanks for the fix!

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.