High memory and CPU usage under metric engine

[evenyag]

What type of bug is this?

Performance issue

What subsystems are affected?

Storage Engine

Minimal reproduce step

Run the latest greptimedb

./greptime standalone start

Ingest metrics via the prometheus write API

What did you expect to see?

CPU and memory should be similar to the mito engine

What did you see instead?

High CPU and memory usage

Put requests are timed out

What operating system did you use?

Ubuntu

What version of GreptimeDB did you use?

0.6

Relevant log output and stack trace

2024-01-23T06:14:22.231308Z DEBUG RegionInvoker::handle_region_request:RegionServer::handle_region_request{region_id="5080946311168(1183, 0)"}:RegionEngine::handle_region_request{engine_type="metric"}: mito2::read::scan_region: Seq scan region 4398063288320(1024, 16777216), request: ScanRequest { projection: Some([2]), filters: [Expr { df_expr: BinaryExpr(BinaryExpr { left: Column(Column { relation: None, name: "k" }), op: Eq, right: Literal(Utf8("__column_5080946311168_Z3JlcHRpbWVfdmFsdWU")) }) }], output_ordering: None, limit: None }, memtables: 1, ssts_to_read: 0, total_ssts: 0
2024-01-23T06:14:22.232017Z DEBUG RegionInvoker::handle_region_request:RegionServer::handle_region_request{region_id="5080946311168(1183, 0)"}:RegionEngine::handle_region_request{engine_type="metric"}: mito2::memtable::time_series: Iter 4398063288320(1024, 16777216) time series memtable, metrics: Metrics { total_series: 1675, num_pruned_series: 1674, num_rows: 1, num_batches: 1, scan_cost: 684.528µs }
2024-01-23T06:14:22.232030Z DEBUG RegionInvoker::handle_region_request:RegionServer::handle_region_request{region_id="5080946311168(1183, 0)"}:RegionEngine::handle_region_request{engine_type="metric"}: mito2::read::seq_scan: Seq scan finished, region_id: 4398063288320(1024, 16777216), metrics: Metrics { build_reader_cost: 398.549µs, scan_cost: 702.259µs, convert_cost: 862ns }, use_parallel: false, parallelism: 4
2024-01-23T06:14:22.232037Z DEBUG RegionInvoker::handle_region_request:RegionServer::handle_region_request{region_id="5080946311168(1183, 0)"}:RegionEngine::handle_region_request{engine_type="metric"}: mito2::read::merge: Merge reader finished, metrics: Metrics { scan_cost: 697.321µs, num_fetch_by_batches: 1, num_fetch_by_rows: 0, num_input_rows: 1, num_duplicate_rows: 0, num_output_rows: 1, num_deleted_rows: 0, fetch_cost: 684.828µs }
2024-01-23T06:14:22.232057Z DEBUG RegionInvoker::handle_region_request:RegionServer::handle_region_request{region_id="5080946311168(1183, 0)"}:RegionEngine::handle_region_request{engine_type="metric"}: mito2::read::scan_region: Seq scan region 4398063288320(1024, 16777216), request: ScanRequest { projection: Some([2]), filters: [Expr { df_expr: BinaryExpr(BinaryExpr { left: Column(Column { relation: None, name: "k" }), op: Eq, right: Literal(Utf8("__column_5080946311168_Z3JlcHRpbWVfdGltZXN0YW1w")) }) }], output_ordering: None, limit: None }, memtables: 1, ssts_to_read: 0, total_ssts: 0
2024-01-23T06:14:22.232739Z DEBUG RegionInvoker::handle_region_request:RegionServer::handle_region_request{region_id="5080946311168(1183, 0)"}:RegionEngine::handle_region_request{engine_type="metric"}: mito2::memtable::time_series: Iter 4398063288320(1024, 16777216) time series memtable, metrics: Metrics { total_series: 1675, num_pruned_series: 1674, num_rows: 1, num_batches: 1, scan_cost: 659.918µs }
2024-01-23T06:14:22.232751Z DEBUG RegionInvoker::handle_region_request:RegionServer::handle_region_request{region_id="5080946311168(1183, 0)"}:RegionEngine::handle_region_request{engine_type="metric"}: mito2::read::seq_scan: Seq scan finished, region_id: 4398063288320(1024, 16777216), metrics: Metrics { build_reader_cost: 379.457µs, scan_cost: 675.774µs, convert_cost: 611ns }, use_parallel: false, parallelism: 4
2024-01-23T06:14:22.232759Z DEBUG RegionInvoker::handle_region_request:RegionServer::handle_region_request{region_id="5080946311168(1183, 0)"}:RegionEngine::handle_region_request{engine_type="metric"}: mito2::read::merge: Merge reader finished, metrics: Metrics { scan_cost: 671.617µs, num_fetch_by_batches: 1, num_fetch_by_rows: 0, num_input_rows: 1, num_duplicate_rows: 0, num_output_rows: 1, num_deleted_rows: 0, fetch_cost: 660.288µs }

[evenyag]

The pprof framegraph shows that the engine issues a scan each time it tries to get the semantic type of a column.

See

greptimedb/src/metric-engine/src/engine/put.rs

Lines 113 to 127 in 19413eb

	// check if the columns exist
	for col in &request.rows.schema {
	if self
	.metadata_region
	.column_semantic_type(metadata_region_id, logical_region_id, &col.column_name)
	.await?
	.is_none()
	{
	return ColumnNotFoundSnafu {
	name: col.column_name.clone(),
	region_id: logical_region_id,
	}
	.fail();
	}
	}

The scan request count is quite high