Commit Graph

13 Commits

Author SHA1 Message Date
Rusty Russell 8f9c48254b plugins: do I/O logging.
I was trying to trace a problem with a plugin, and needed this.

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
2019-05-31 18:36:38 +02:00
Simon Vrouwe db57d9c5d2 lightningd: suppress IO_OUT logging for getlog command
Before this, the response of `getlog io` blew up quickly
when called multiple times.
2019-05-26 23:53:20 +00:00
Rusty Russell 0b79538b18 lightningd: hang up on clients if they make us run out of memory.
This happened with the 800M JSON for the MCP listchannels on the raspberry
pi, and tal calls abort() by default.

We switch to raw malloc here; we could override the error hook for
tal, but this is neater since we're doing low-level things anyway,

I tested it manually with this patch:

   diff --git a/lightningd/json_stream.c b/lightningd/json_stream.c
   index cec9f5771..206ba37c0 100644
   --- a/lightningd/json_stream.c
   +++ b/lightningd/json_stream.c
   @@ -43,6 +43,14 @@ static void free_json_stream_membuf(struct json_stream *js)
    	free(membuf_cleanup(&js->outbuf));
    }
    
   +static void *membuf_realloc_hack(struct membuf *mb, void *rawelems,
   +				 size_t newsize)
   +{
   +	if (newsize > 1000000000)
   +		return NULL;
   +	return realloc(rawelems, newsize);
   +}
   +
    struct json_stream *new_json_stream(const tal_t *ctx,
    				    struct command *writer,
    				    struct log *log)
   @@ -53,7 +61,7 @@ struct json_stream *new_json_stream(const tal_t *ctx,
    	js->reader = NULL;
    	/* We don't use tal here, because we handle failure externally (tal
    	 * helpfully aborts with a msg, which is usually right) */
   -	membuf_init(&js->outbuf, malloc(64), 64, membuf_realloc);
   +	membuf_init(&js->outbuf, malloc(64), 64, membuf_realloc_hack);
    	tal_add_destructor(js, free_json_stream_membuf);
    #if DEVELOPER
    	js->wrapping = tal_arr(js, jsmntype_t, 0);

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
2019-05-22 11:28:44 +00:00
Rusty Russell 20006b6553 lightningd: speed low-level json formatting.
Make json_start_member allocate extra space, which caller can directly
print into, and also make caller call js_written_some() itself.

MCP results from 5 runs, min-max(mean +/- stddev):
	store_load_msec:35071-36817(35617.2+/-7e+02)
	vsz_kb:2637488
	store_rewrite_sec:35.790000-37.500000(36.6375+/-0.63)
	listnodes_sec:0.690000-0.780000(0.72+/-0.035)
	listchannels_sec:34.600000-36.340000(35.36+/-0.77)
	routing_sec:30.310000-30.730000(30.445+/-0.17)
	peer_write_all_sec:50.830000-52.750000(51.82+/-0.89)

MCP notable changes from previous patch (>1 stddev):
	-listnodes_sec:0.720000-0.950000(0.86+/-0.077)
	+listnodes_sec:0.690000-0.780000(0.72+/-0.035)
	-listchannels_sec:40.300000-41.080000(40.668+/-0.29)
	+listchannels_sec:34.600000-36.340000(35.36+/-0.77)

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
2019-04-09 12:37:16 -07:00
Rusty Russell dc6d53e787 lightningd: don't bother pretty-printing JSON.
This doesn't result in a speedup for our benchmark, since we use the
cli tool which does the formatting.

MCP results from 5 runs, min-max(mean +/- stddev):
	store_load_msec:33422-36830(35196.2+/-1.2e+03)
	vsz_kb:2637488
	store_rewrite_sec:36.030000-37.630000(36.794+/-0.52)
	listnodes_sec:0.720000-0.950000(0.86+/-0.077)
	listchannels_sec:40.300000-41.080000(40.668+/-0.29)
	routing_sec:30.440000-31.030000(30.69+/-0.2)
	peer_write_all_sec:50.060000-52.800000(51.416+/-0.91)

MCP notable changes from 2 patches ago (>1 stddev):
	-listchannels_sec:48.560000-55.680000(52.642+/-2.7)
	+listchannels_sec:40.300000-41.080000(40.668+/-0.29)

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
2019-04-09 12:37:16 -07:00
Rusty Russell 465065691f json_add_hex: wire in at a lower level.
This is one of the more significant fields we print, but there's no
need to allocate a temp buffer or escape the resulting string.

MCP results from 5 runs, min-max(mean +/- stddev):
	store_load_msec:34048-36002(35070.4+/-8.5e+02)
	vsz_kb:2637488
	store_rewrite_sec:35.110000-38.120000(36.604+/-1.2)
	listnodes_sec:0.830000-1.020000(0.95+/-0.065)
	listchannels_sec:48.560000-55.680000(52.642+/-2.7)
	routing_sec:29.800000-33.170000(30.536+/-1.3)
	peer_write_all_sec:49.260000-52.490000(50.316+/-1.1)

MCP notable changes from previous patch (>1 stddev):
	-listchannels_sec:55.390000-58.110000(56.998+/-0.99)
	+listchannels_sec:48.560000-55.680000(52.642+/-2.7)

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
2019-04-09 12:37:16 -07:00
Rusty Russell 6cac2c959e lightningd: log IO only on actual output.
This causes natural batching, rather than on every little addition of
JSON formatting.

Before, to listchannels 100,000 channels took 82.48 seconds, after
6.82 seconds.

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
2019-04-08 04:41:43 +00:00
Rusty Russell 53423e8a55 lightningd: re-enable IO logging for JSON output.
Hex format is terrible, but sometimes it's the only way to tell WTF is
going on.

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
2019-02-21 00:44:57 +00:00
Rusty Russell 26dda57cc0 utils: make tal_arr_expand safer.
Christian and I both unwittingly used it in form:

	*tal_arr_expand(&x) = tal(x, ...)

Since '=' isn't a sequence point, the compiler can (and does!) cache
the value of x, handing it to tal *after* tal_arr_expand() moves it
due to tal_resize().

The new version is somewhat less convenient to use, but doesn't have
this problem, since the assignment is always evaluated after the
resize.

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
2019-01-15 12:01:38 +01:00
Christian Decker dd2696a88b json: Add function to duplicate a json_stream
Will be used in the next commit to fan out notifications to multiple
subscribing plugins. We can't just use `tal_dup` from outside since
the definition is hidden outside the compilation unit.

Signed-off-by: Christian Decker <decker.christian@gmail.com>
2018-12-30 14:36:02 +01:00
Rusty Russell 10260e2f24 lightningd: expose lower-level APIs.
We need these for literal copying of requests between plugin and client.

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
2018-12-10 00:00:50 +00:00
Rusty Russell e0d14bddb9 jsonrpc: allow multiple commands at once.
We now keep multiple commands for a json_connection, and an array of
json_streams.

When a command wants to write something, we allocate a new json_stream
at the end of the array.

We always output from the first available json_stream; once that
command has finished, we free that and move to the next.  Once all are
done, we wake the reader.

This means we won't read a new command if output is still pending, but
as most commands don't start writing until they're ready to write
everything, we still get command parallelism.

In particular, you can now 'waitinvoice' and 'delinvoice' and it will
work even though the 'waitinvoice' blocks.

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
2018-11-20 16:51:19 +01:00
Rusty Russell e17f69ce2d json_stream: disentangle JSON handling from command.
We promote 'struct json_stream' to contain the membuf; we only attach
the json_stream to the command when we actually call
json_stream_success / json_stream_fail.

This means we are closer to 'struct json_stream' being an independent
layer; the tests are already modified to use it directly to create
JSON.

This is also the first step toward re-enabling non-serial command
execution.

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
2018-11-20 16:51:19 +01:00