Investigate http -> pipelines -> blackhole

[blt]

This issue is a record of and parent to the investigation of vector's performance when configured as in this gist.

Inbound http_gen -- built from lading at SHA 0da91906d56acc899b829cea971d79f13e712e21-- is configured like so:

worker_threads: 1
prometheus_addr: "0.0.0.0:9001"

targets:
  vector:
    headers: {}
    target_uri: "http://localhost:8282/"
    bytes_per_second: "500 Mb"
    parallel_connections: 10
    block_sizes: ["1Kb", "2Kb"]
    method:
      post:
        maximum_prebuild_cache_size_bytes: "256 Mb"
        variant:
          static:
            static_path: "/home/blt/projects/com/github/timberio/vector/investigation/input.log"

Referenced input.log can be found here.

[blt]

An attempt has been made to get the referenced vector.toml et al into a soak. This work is ongoing in #10142 but is blocked pending a minikube bug.

[blt]

Absent a CI soak we use the older methods from #8512 et al for measuring throughput. Until further notice vector is run like so:

> firejail --noprofile --rlimit-as=8g --cpu=0,1,2,3,4,5,6,7 ./target/release/vector --config ~/projects/com/github/timberio/vector/investigation/vector.toml

and http_gen is run like so:

> firejail --noprofile --cpu=8 ./target/release/http_gen --config-path ~/projects/com/github/timberio/vector/investigation/http_gen.yaml

Under these conditions we find:

SHA	http_gen generation Kb/s	http bytes processed Kb/s	blackhole receipt Kb/s
127f05b	27	30	163

Please note, these values are in kibibytes. Please also be aware that throughput varied wildly and these are median values taken over a five minute sample.

[blt]

Captured perf command:

> perf record --output=/tmp/vector-perf.data --compression-level=10 --call-graph=dwarf ./target/release/vector --config ~/projects/com/github/timberio/vector/investigation/vector.toml

Vector built like so:

> CARGO_PROFILE_RELEASE_DEBUG=2 cargo build --release

Unfortunately even compressed the data file is 1.5G and cannot be compressed further.

flamegraph

Items of concern:

• regex::exec::ExecBuilder::build appears as a hot spot, implying we are building regexes in a loop.
• major cost centers show in VRL, work ongoing in Vrl Performance #9811
• MatchDatadogQueryFn in VRL's stdlib is a major cost center, has been recently introduced

[blt]

/cc @vladimir-dd

[vladimir-dd]

Right, thanks @blt for running this test.
Yes, I'd expect MatchDatadogQueryFn to be one of performance bottlenecks - it's called once per pipeline for each event(plus for category processors), and I assume we are calling regex::exec::ExecBuilder::build from this function - seems like we build regexes at runtime, not during vrl compilation.

[blt]

Building on the last comment, @leebenson noted in slack that the match datadog query is caching regex, per

vector/lib/vrl/stdlib/src/match_datadog_query.rs

Lines 284 to 310 in d8ed1b5

	#[cached(
	type = "SizedCache<String, Regex>",
	create = "{ SizedCache::with_size(10) }",
	convert = r#"{ to_match.to_owned() }"#
	)]
	/// Returns compiled word boundary regex. Cached to avoid recompilation in hot paths.
	fn word_regex(to_match: &str) -> Regex {
	Regex::new(&format!(
	r#"\b{}\b"#,
	regex::escape(to_match).replace("\\*", ".*")
	))
	.expect("invalid wildcard regex")
	}
	#[cached(
	type = "SizedCache<String, Regex>",
	create = "{ SizedCache::with_size(10) }",
	convert = r#"{ to_match.to_owned() }"#
	)]
	/// Returns compiled wildcard regex. Cached to avoid recompilation in hot paths.
	fn wildcard_regex(to_match: &str) -> Regex {
	Regex::new(&format!(
	"^{}$",
	regex::escape(to_match).replace("\\*", ".*")
	))
	.expect("invalid wildcard regex")
	}

. It's unknown how many instances we have at runtime now but 10 does seem small for the posted config.

[blt]

From @JeanMertz in slack:

I don't know the ins and outs here, but aot compilation can happen in the compile step for functions:

vector/lib/vrl/stdlib/src/match_datadog_query.rs

Lines 44 to 64 in d8ed1b5

	fn compile(
	&self,
	_state: &state::Compiler,
	_ctx: &FunctionCompileContext,
	mut arguments: ArgumentList,
	) -> Compiled {
	let value = arguments.required("value");
	let query_value = arguments.required_literal("query")?.to_value();
	// Query should always be a string.
	let query = query_value
	.try_bytes_utf8_lossy()
	.expect("datadog search query not bytes");
	// Compile the Datadog search query to AST.
	let node = parse(&query).map_err(|e| {
	Box::new(ExpressionError::from(e.to_string())) as Box<dyn DiagnosticError>
	})?;
	Ok(Box::new(MatchDatadogQueryFn { value, node }))
	}

Take a look at the parse_grok function that does aot compilation of the grok pattern:

vector/lib/vrl/stdlib/src/parse_grok.rs

Lines 88 to 118 in e399c84

	fn compile(
	&self,
	_state: &state::Compiler,
	_ctx: &FunctionCompileContext,
	mut arguments: ArgumentList,
	) -> Compiled {
	let value = arguments.required("value");
	let pattern = arguments
	.required_literal("pattern")?
	.to_value()
	.try_bytes_utf8_lossy()
	.expect("grok pattern not bytes")
	.into_owned();
	let mut grok = grok::Grok::with_patterns();
	let pattern = Arc::new(
	grok.compile(&pattern, true)
	.map_err(|e| Box::new(Error::InvalidGrokPattern(e)) as Box<dyn DiagnosticError>)?,
	);
	let remove_empty = arguments
	.optional("remove_empty")
	.unwrap_or_else(|| expr!(false));
	Ok(Box::new(ParseGrokFn {
	value,
	pattern,
	remove_empty,
	}))
	}

This only works if the argument you want to use for aot compilation only takes literals, which does seem to be the case for match_datadog_query:

vector/lib/vrl/stdlib/src/match_datadog_query.rs

Line 51 in d8ed1b5

let query_value = arguments.required_literal("query")?.to_value();

So it seems all the ingredients are there to do as much as possible at the compile-step, instead of during runtime for each event (assuming caching isn't working).

[blt]

REF #10202

[blt]

REF #10189

[vladimir-dd]

REF #10200

[blt]

We are now investigating with the following configs run as above. Lading's version is e81610664b059422b774c770e741569c6ef8cf08.

We see from the soaks that both http_pipelines_blackhole and http_pipelines_no_grok_blackhole suffer similarly poor performance. In #11086 we investigated removing onig to get a clearer sense of allocation patterns in these configurations and go not real leads beyond what we already knew: our cloning of Event and vrl::Value is an allocation churn point.

For vector at 0736db5 I have the two offwaketime flamegraphs. The first is for http_pipelines_blackhole and the second the no-grok variant:

The difference between these two graphs are non-trivial but consider how similar their runtimes are an the no-grok variant is a chopped version of the grok variant I suspect that addressing issues in no-grok is a fruitful path forward. PollStrategy::poll_streams, Fanout::start_send, EventsSend::emit_metrics stand out as major culprits of forcing vector off-CPU.

[blt]

Now that #11633 is correct we have an interesting lead on what's happening here. Consider this configuration versus this configuration. Both implement the same basic idea but the no_pipelines variant is the "unrolled" version of the former, that is, it does not use the pipelines construct. The no_pipelines variant is almost twice as fast as the pipelines variant -- hat tip to @lukesteensen for the idea to try this out -- and we get some interesting data on why the unrolled version is faster.

Consider the following graphs. I have run the unrolled variant first, followed by a pause, and then the pipelines version. Here we see throughput, which, aside from an initial high spike shows that the unrolled version has maybe twice better throughput:

Throughput is measured from lading, that is, the load generating tool. When we inspect Vector's self-instrumentation we find an interesting pattern. On the left-hand side the total number of processed events in Transform instances are roughly the same as on the right except that the right-hand side shows much higher internal Event traffic in the filter and noop components.

Utilization bears the out further. On the left-hand side Vector runtime is dominated transforms present in the configuration, especially in those with complicated datadog_search conditions, presenting a valuable optimization target. On the right-hand side runtime is dominated by truthy/falsy components, a quirk of how filtering is achieved in pipelines:

To explain this, the pipeline "filter" is not a single Transform instance but is actually two instances the "truthy" side and the "falsy" side with terminals on the negations of each boolean. This means every condition is run twice, Event instances are cloned twice etc etc. The noop is used as a coalescing terminal in the pipeline and shows up heavily in utilization as well, something that the "unrolled" variant is able to side-step entirely.

The pipeline mechanism in Vector as of this writing works by "expanding" sub-transforms into a sub-topology of the main topology and guides data flow through this sub-topology with these implicit filter/expand/routing constructs of non-zero cost. Consider that if the pipelines filter were a single rather than double runtime component the pipeline configuration would pay the cost of only a single condition check per filter per Event, rather than two. The expansion mechanism also awkwardly thwarts other optimizations that the rest of the Vector topology has picked up. Consider that PipelinesConfig does not turn into a Pipelines implementing some Transform. If it, say, implemented FunctionTransform then we could run multiple copies of it in parallel, improving CPU saturation. See #10265 for the kind of improvement this optimization brings.

As a next step I believe we should contrive to have PipelineFilterConfig implement TransformConfig::build and avoid the falsy/truthy penalty. More generally, PipelinesConfig should implement TransformConfig::build and the resulting Transform instance will then be able to pick up other topology optimizations. I have a hunch that the expansion approach extant in the code base today should be gradually walked back and we should not have TransformConfig instances that don't implement ::build. Ideally we can contrive to lose Noop entirely. As it is, the expansion mechanism in use in the pipelines means we lose optimizations that are done to the broader topology and optimization of the pipelines ends up being a specialized project.

[blt]

As of 06e05be the main bottleneck per #12267 is the use of "enriched" mode in VRL's parse_user_agent. Resolving this -- by switching to "fast" mode -- suggests that the next areas of work are:

• Incorporate new Lookup code into VRL and vector  #7070, specifically we spend a lot time right here. Lookup parsing contributes roughly 7% of execution time.
• Runtime regex compilation counts for 9% of execution time, likely this. Call sites for these functions are in VRL stdlib and src/conditions/datadog_search.rs.
• VRL user-agent parsing is a bottleneck in http -> pipelines -> blackhole #12267 as mentioned.

[JeanMertz]

Runtime regex compilation counts for 9% of execution time, likely this. Call sites for these functions are in VRL stdlib and src/conditions/datadog_search.rs.

To expand on this, the only function in VRL's stdlib using word_regex and wildcard_regex, is match_datadog_query.

[jszwedko]

Closing since this transform was removed.