Program spending 3ms in an empty concat

[ryzhyk]

I am trying to understand the CPU profile of my DD program constructed using the logging API. The profile is dominated by Concat operators: out of ~0.5s total time spent in the dataflow, approximately 0.3s is spread across 200 or so Concatenate operators. This is not in itself too surprising, since the program contains a collection built by concatenating hundreds of rules. The weird part is that many of the operators actually concatenate an empty collection, e.g., according to the profile the program spends 3ms evaluating c1.concat(c2), where collection c2 has been empty throughout the run of the program.

Profiles vary slightly across runs, but the overall picture is pretty consistent.

I would appreciate any help in understanding what could be going on here: Is it possible that DD spends >0s (in fact, much more than that) concatenating an empty collection? Could this be an artifact or how DD reports operator runtimes? Or is this most likely a bug in my profiling code?

[frankmcsherry]

Super interesting! That is a (relatively) large amount of time!

cc @li1 @utaal @vasia who are currently looking at "performance debugging" as a thing, and who may want to follow.

I'm not aware of a reason that concatenate would be mis-reported, so while it could in principle be your log munching, it could also be something interesting and weird in concatenate. It is a bit hard to say without more details (and which details would help are @li1's purview), but here are some random thoughts:

1. My most common experience with "surprisingly expensive operators" is that this operator does some un-expected system-level work. For example, the first operator in a chain is the one who needs to allocate memory from the kernel; other operators after it do the same thing, but they can re-use these allocations and don't eat the same cost.
2. Do you have a sense for the distribution of the times making up the 0.3s? As in, is it a matter of too many calls into a cheap but not free operator, or one surprisingly long call, or a mix, or .. We can get you some code that does good histogramming of the distribution, and should probably drop that in to the diagnosis workflow.
3. The concatenate operator really doesn't do much: in each call it walks through its input handles and moves any input buffers into its output, often without a copy (e.g. if no serialization, then each of these should just be moving a pointer).
4. One potential cost that could be attributed to concatenate is if large numbers of operators re-use its outputs, the "sending" will include copying these records to the inputs of each of the downstream operators. This could be a moment where more memory is required from the kernel, but it is all speculation based on your dataflow graph.

I'm sure there are other issues, and happy to help try and figure out. But, I am also super interested in the performance debugging process and may act all weird and ask you to try things, rather than just grab your code and try to fix it. If that becomes infuriating at any point, or we flounder with the diagnosis process, feel free to bundle things up and point me at it.

[frankmcsherry]

e.g., according to the profile the program spends 3ms evaluating c1.concat(c2), where collection c2 has been empty throughout the run of the program.

Fwiw, the emptiness of one input doesn't mean concat should go fast. It should take time roughly proportional to the sum of the amount of data moving through it (it just forwards records on either input), and the proportionality is meant to be pretty good (just pointer manipulation).

So, it could be that one input is empty, and the other is 1TB that you then drop; that could make concatenate look expensive (I'm sure that isn't what you are doing, but .. just so you know!).

[ryzhyk]

First, to add more context, in this particular scenario the program only receives a few input records (probably, 10 or so), and none of the computed collections is large (in particular, the collection computed by concatenating 200 other collections only contains 84 records, and it is the biggest one in this dataflow). So this is the case of a very large program processing a tiny amount of data.

The concatenate operator really doesn't do much: in each call it walks through its input handles and moves any input buffers into its output, often without a copy (e.g. if no serialization, then each of these should just be moving a pointer).

So, every time I call c1.concat(c2), it copies the content of both c1 and c2? And if I do this 200 times for the same c1 and different c2s, it will copy accumulated records 200 times? I noticed that the Scope::concatenate, which you pointed me to, concatenates many collections in one go. Is it possible to have a version of Collection::concat that concatenates multiple collections more efficiently?

My most common experience with "surprisingly expensive operators" is that this operator does some un-expected system-level work. For example, the first operator in a chain is the one who needs to allocate memory from the kernel; other operators after it do the same thing, but they can re-use these allocations and don't eat the same cost.

This sounds plausible. I imagine that, as the empty dataflow is receiving its first few records, it allocates buffers all over the place. But I don't think there is an easy way to correlate syscalls with operators?

Do you have a sense for the distribution of the times making up the 0.3s? As in, is it a matter of too many calls into a cheap but not free operator, or one surprisingly long call, or a mix, or .. We can get you some code that does good histogramming of the distribution, and should probably drop that in to the diagnosis workflow.

Like I said, there are only a few inputs records in this experiment, so the operator is probably only invoked several times. I can get some real numbers tomorrow.

One potential cost that could be attributed to concatenate is if large numbers of operators re-use its outputs, the "sending" will include copying these records to the inputs of each of the downstream operators. This could be a moment where more memory is required from the kernel, but it is all speculation based on your dataflow graph.

Is there a way to dump the dataflow graph, so I can see who consumes the outputs of concat?

[frankmcsherry]

So this is the case of a very large program processing a tiny amount of data.

Ooo, very interesting then.

So, every time I call c1.concat(c2), it copies the content of both c1 and c2? And if I do this 200 times for the same c1 and different c2s, it will copy accumulated records 200 times?

When you call concat, we build a concatenate operator that responds to changes in the inputs to concat. The way it responds to any input change is by presenting it as an output change as well. If you call concat 200 times for the same c1 you will assemble 200 concatenate operators, each of which will need its own copy of c1 (only the first use of a stream can avoid a copy; subsequent uses end up needing copies).

I noticed that the Scope::concatenate, which you pointed me to, concatenates many collections in one go. Is it possible to have a version of Collection::concat that concatenates multiple collections more efficiently?

So Scope::concatenate is the best way to concatenate multiple collections (edit: If you look at the implementation of Collection::concat, it just calls in to Scope::concatenate. It should be much better than a sequence of concat calls, which has the potential to end up doing work quadratic in the number of relations. If you are chaining together 200 calls to concat, I'd recommend replacing them with one call to concatenate and see if that helps!

Is there a way to dump the dataflow graph, so I can see who consumes the outputs of concat?

The Operates and Channels events in the timely logs should reveal this information. They don't necessarily dump it in the most accessible format, but it should be a start. Cardinality information might be easy to get, for example.

[frankmcsherry]

Is it possible to have a version of Collection::concat that concatenates multiple collections more efficiently?

Oh I see. Sorry. You have easy access to timely's Scope::concatenate, but that doesn't make life immediately easy for users of differential's Collection type.

1. If this is ever painful, you can always drop down in to timely and use its operators. Any collection has an .inner field which is its timely stream, you can do whatever you want with timely streams, and then pop back up into a collection with the .as_collection() method.
2. We should totally be able to add some concatenate to differential, but ... Scope::concatenate is done how it is done to avoid requiring a stream or collection; there are times where you have an empty iterator, and things still need to work.

The following method (or something very close to it) should work to more efficiently concatenate many collections:

fn concatenate<G, D, R, I>(scope: &mut G, iterator: I) -> Collection<G, D, R>
where I : IntoIterator<Collection<G, D, R>>
{
    scope::concatenate(iterator.map(|x| x.inner))
        .as_collection()
}

[ryzhyk]

Thanks for the explanation!

I'd recommend replacing them with one call to concatenate and see if that helps!

This seems very promising! Will try first thing tomorrow.

The Operates and Channels events in the timely logs should reveal this information. They don't necessarily dump it in the most accessible format, but it should be a start. Cardinality information might be easy to get, for example.

Aha, I am already familiar with Operates. I guess Channels is the missing part of the equation.

[frankmcsherry]

Two methods collection::concatenate and Collection::concatenate added in #170.

[li1]

Hey @ryzhyk,

I just added a repo under https://github.com/li1/dataflow-viz that might help you with basic dataflow visualization.

It's currently quite crude (e.g., it doesn't respect Channel input/output ports) and I haven't tested it a lot, but it might at least support you in sanity checking your dataflow. Also, it's just a few lines of Clojure, so should be really easy to extend.

[ryzhyk]

I am seeing a massive improvement with #170. The total runtime is down to 0.28s from 0.5s, with concatenation no longer being the dominant component. Thanks heaps for helping out!

[ryzhyk]

@li1, many thanks for the pointer! My approach so far has been to use the logging API directly, as I am usually able to extract the information I need with only few lines of code. Part of the reason is that this way it's easier for me to add DDlog-specific annotations to the output. But if dumping the dataflow graph proves tricky, I'll be very happy to try your tool.

I do wish all these nice profiling tools you guys are writing were more tightly integrated with DD, e.g., I would love to be able to call a DD library function to dump dataflow into graphviz :) I just chatted with @utaal and he mentioned that things may indeed start moving in that direction.

[frankmcsherry]

Closing as "resolved" due to the multiway concat cleaning up a bunch of the problems. Feel free to re-open if that is wrong.