ProfileEvents
┌─event_name─────────────────────┬─event_value─┐
...
│ NetworkSendElapsedMicroseconds │ 61 │
│ NetworkSendBytes │ 2323 │
│ SelectedRows │ 1 │
│ SelectedBytes │ 4104 │
│ RealTimeMicroseconds │ 11529 │
│ SystemTimeMicroseconds │ 7898 │
│ OSCPUVirtualTimeMicroseconds │ 7898 │
│ OSReadChars │ 990 │
│ OSWriteChars │ 866 │
└────────────────────────────────┴─────────────┘
count() query did not read anything
┌─explain─────────────────────────────────────────────────────────────────────────┐
│ Expression ((Projection + Before ORDER BY)) │
│ Header: event_name String │
│ event_value UInt64 │
│ ArrayJoin (ARRAY JOIN) │
│ Header: pe Tuple(String, UInt64) │
│ Expression ((Before ARRAY JOIN + (Projection + Before ORDER BY))) │
│ Header: pe Array(Tuple(String, UInt64)) │
│ Filter (WHERE) │
│ Header: ProfileEvents Map(String, UInt64) │
│ SettingQuotaAndLimits (Set limits and quota after reading from storage) │
│ Header: equals(type, 'QueryFinish') UInt8 │
│ query_id String │
│ ProfileEvents Map(String, UInt64) │
│ ReadFromMergeTree │
│ Header: equals(type, 'QueryFinish') UInt8 │
│ query_id String │
│ ProfileEvents Map(String, UInt64) │
└─────────────────────────────────────────────────────────────────────────────────┘
force_index_by_dateforce_primary_keyforce_data_skipping_indicesNow get back to those two queries (very slow and just slow)
Let's compare ProfileEvents
WITH
faster AS
(
SELECT pe.1 AS event_name, pe.2 AS event_value
FROM
(
SELECT ProfileEvents.Names, ProfileEvents.Values
FROM system.query_log
WHERE (query_id = 'd18fb820-4075-49bf-8fa3-cd7e53b9d523') AND (type = 'QueryFinish') AND (event_date = today())
)
ARRAY JOIN arrayZip(ProfileEvents.Names, ProfileEvents.Values) AS pe
),
slower AS
(
SELECT pe.1 AS event_name, pe.2 AS event_value
FROM
(
SELECT ProfileEvents.Names, ProfileEvents.Values
FROM system.query_log
WHERE (query_id = '22ffbcc0-c62a-4895-8105-ee9d7447a643') AND (type = 'QueryFinish') AND (event_date = today())
)
ARRAY JOIN arrayZip(ProfileEvents.Names, ProfileEvents.Values) AS pe
)
SELECT
event_name,
formatReadableQuantity(slower.event_value) AS slower_value,
formatReadableQuantity(faster.event_value) AS faster_value,
round((slower.event_value - faster.event_value) / slower.event_value, 2) AS diff_q
FROM faster
LEFT JOIN slower USING (event_name)
WHERE diff_q > 0.05
ORDER BY event_name ASC
SETTINGS join_use_nulls = 1
Query id: 18c49832-5f32-4a08-8c8b-1ccabdcb5356
12 rows in set. Elapsed: 0.296 sec. Processed 1.29 million rows, 1.54 GB (4.34 million rows/s., 5.19 GB/s.)
┌event_name───────────────────────┬slower_value───┬faster_value───┬diff_q┐
│DiskReadElapsedMicroseconds │2.08 billion │34.98 million │ 0.98│
│FileOpen │279.00 │253.00 │ 0.09│
│MarkCacheMisses │13.00 │10.00 │ 0.23│
│NetworkReceiveElapsedMicroseconds│3.28 thousand │1.96 thousand │ 0.4│
│NetworkSendBytes │14.03 million │5.24 million │ 0.63│
│OSReadBytes │51.61 billion │106.50 thousand│ 1│
│OpenedFileCacheMisses │279.00 │253.00 │ 0.09│
│RealTimeMicroseconds │2.51 billion │645.00 million │ 0.74│
│Seek │4.94 thousand │1.97 thousand │ 0.6│
│SelectedParts │55.00 │51.00 │ 0.07│
│SelectedRanges │55.00 │51.00 │ 0.07│
│SoftPageFaults │729.52 thousand│193.42 thousand│ 0.73│
└─────────────────────────────────┴───────────────┴───────────────┴──────┘
SELECT COLUMNS('q90') APPLY x -> round(avg(x), 2)
FROM
(
WITH
ProfileEvents['MarkCacheHits'] AS m_hits,
ProfileEvents['MarkCacheMisses'] AS m_misses,
if(m_hits OR m_misses, m_hits / (m_hits + m_misses), 0) AS m_hits_q,
ProfileEvents['UncompressedCacheHits'] AS u_hits,
ProfileEvents['UncompressedCacheMisses'] AS u_misses,
if(u_hits OR u_misses, u_hits / (u_hits + u_misses), 0) AS u_hits_q,
ProfileEvents['OSReadChars'] AS read_chars,
ProfileEvents['OSReadBytes'] AS read_bytes,
read_chars - read_bytes AS page_cache_hit_bytes,
if((read_chars > 0) AND (read_bytes > 0) AND (read_chars > read_bytes),
page_cache_hit_bytes / read_chars,
0) AS p_hits_q
SELECT
normalized_query_hash,
quantileExactIf(0.9)(query_duration_ms, m_hits_q < 0.5) AS m_hit_0_50_q90,
quantileExactIf(0.9)(query_duration_ms, m_hits_q >= 0.5) AS m_hit_50_100_q90,
quantileExactIf(0.9)(query_duration_ms, u_hits_q < 0.5) AS u_hit_0_50_q90,
quantileExactIf(0.9)(query_duration_ms, u_hits_q >= 0.5) AS u_hit_50_100_q90
quantileExactIf(0.9)(query_duration_ms, p_hits_q < 0.5) AS p_hit_0_50_q90,
quantileExactIf(0.9)(query_duration_ms, p_hits_q >= 0.5) AS p_hit_50_100_q90,
FROM system.query_log
WHERE event_date >= yesterday()
GROUP BY normalized_query_hash
)
Row 1:
──────
round(avg(m_hit_0_50_q90), 2): 16238.45
round(avg(m_hit_50_100_q90), 2): 1478.91
round(avg(u_hit_0_50_q90), 2): 16739.76
round(avg(u_hit_50_100_q90), 2): 971.83
round(avg(p_hit_0_50_q90), 2): 17373.8
round(avg(p_hit_50_100_q90), 2): 1049.97
WITH
(SELECT value FROM system.metrics WHERE metric = 'MemoryTracking') AS rss,
(
SELECT sum(bytes) AS bytes
FROM
(
SELECT sum(total_bytes) AS bytes FROM system.tables WHERE engine IN ('Join','Memory','Buffer','Set')
UNION ALL
SELECT sum(value::UInt64) AS bytes FROM system.asynchronous_metrics WHERE metric LIKE '%CacheBytes'
UNION ALL
SELECT sum(memory_usage::UInt64) AS bytes FROM system.processes
UNION ALL
SELECT sum(memory_usage::UInt64) AS bytes FROM system.merges
UNION ALL
SELECT sum(bytes_allocated) AS bytes FROM system.dictionaries
UNION ALL
SELECT sum(primary_key_bytes_in_memory_allocated) AS bytes FROM system.parts
)
) AS used_memory
SELECT
formatReadableSize(rss) AS rss_,
formatReadableSize(used_memory) AS used_memory_,
formatReadableSize(rss - used_memory) AS fragmentation_
┌─rss_───────┬─used_memory_─┬─fragmentation_─┐
│ 216.20 GiB │ 208.23 GiB │ 7.97 GiB │
└────────────┴──────────────┴────────────────┘
Memory limit exceeded (for query)Let's run the following query
SELECT event_type, repo_name, actor_login, count()
FROM github_events
GROUP BY event_type, repo_name, actor_login
ORDER BY count() DESC
LIMIT 10
↑ Progress: 1.29 billion rows, 17.82 GB (141.08 million rows/s., 1.95 GB/s.) ███████████████████████████████▍
(32.1 CPU, 33.91 GB RAM) 40%
0 rows in set. Elapsed: 10.113 sec. Processed 1.29 billion rows, 17.82 GB (127.45 million rows/s., 1.76 GB/s.)
Received exception from server (version 22.2.1):
Code: 241. DB::Exception: Received from localhost:9000. DB::Exception:
Memory limit (for query) exceeded: would use 32.00 GiB (attempt to allocate chunk of 4555008 bytes),
maximum: 32.00 GiB: While executing AggregatingTransform. (MEMORY_LIMIT_EXCEEDED)
GROUP BY/ORDER BY:
SELECT event_type, repo_name, actor_login, count()
FROM github_events
GROUP BY event_type, repo_name, actor_login
ORDER BY count() DESC
LIMIT 10
SETTINGS
max_bytes_before_external_group_by = '1G',
max_bytes_before_external_sort = '1G',
max_threads = 16
10 rows in set. Elapsed: 181.615 sec.
Processed 3.12 billion rows, 46.56 GB
(17.18 million rows/s., 256.39 MB/s.)
SELECT event_type, repo_name, actor_login, count()
FROM github_events
GROUP BY event_type, repo_name, actor_login
ORDER BY count() DESC
LIMIT 10
SETTINGS
max_memory_usage = '256Gi',
memory_profiler_sample_probability = 1
Query id: 1b1d1608-40f9-448a-84ae-a199ca76156d
10 rows in set. Elapsed: 72.430 sec.
Processed 3.12 billion rows, 46.53 GB
(43.07 million rows/s., 642.35 MB/s.)
┌─event_type──┬─repo_name───────────────────────┬─actor_login─────┬─count()─┐
│ PushEvent │ peter-clifford/grax-hd-trial │ peter-clifford │ 3097263 │
│ PushEvent │ Lombiq/Orchard │ LombiqBot │ 2471077 │
│ CreateEvent │ eclipse/eclipse.platform.common │ eclipse │ 1889286 │
│ PushEvent │ unitydemo2/Docworks │ unitydemo2 │ 1779811 │
│ PushEvent │ commit-b0t/commit-b0t │ commit-b0t │ 1688188 │
│ PushEvent │ KenanSulayman/heartbeat │ KenanSulayman │ 1595611 │
│ PushEvent │ chuan12/shenzhouzd │ chuan12 │ 1449096 │
│ PushEvent │ othhotro/Roo.Exe │ othhotro │ 1437709 │
│ CreateEvent │ direwolf-github/my-app │ direwolf-github │ 1426236 │
│ DeleteEvent │ direwolf-github/my-app │ direwolf-github │ 1425781 │
└─────────────┴─────────────────────────────────┴─────────────────┴─────────┘
EXPLAIN PIPELINE to get those processors:
EXPLAIN PIPELINE
SELECT
event_type,
repo_name,
actor_login,
count()
FROM github_events
GROUP BY
event_type,
repo_name,
actor_login
ORDER BY count() DESC
LIMIT 10
┌─explain──────────────────────────────────────────┐
│ (Expression) │
│ ExpressionTransform │
│ (Limit) │
│ Limit │
│ (Sorting) │
│ MergeSortingTransform │
│ LimitsCheckingTransform │
│ PartialSortingTransform │
│ (Expression) │
│ ExpressionTransform │
│ (Aggregating) │
│ Resize 32 → 1 │
│ AggregatingTransform × 32 │
│ StrictResize 32 → 32 │
│ (Expression) │
│ ExpressionTransform × 32 │
│ (SettingQuotaAndLimits) │
│ (ReadFromMergeTree) │
│ MergeTreeThread × 32 0 → 1 │
└──────────────────────────────────────────────────┘
SELECT
event_type,
repo_name,
actor_login,
count()
FROM github_events
GROUP BY
event_type,
repo_name,
actor_login
ORDER BY count() DESC
LIMIT 10
SETTINGS
max_memory_usage = '256Gi',
log_processors_profiles = 1
Query id: d7edb6c5-d0ce-4baf-87d4-68b5721ff6d9
10 rows in set. Elapsed: 73.262 sec. Processed 3.12 billion rows, 46.53 GB (42.58 million rows/s., 635.06 MB/s.)
SELECT
name,
sum(elapsed_us) / 1e6 AS elapsed,
sum(need_data_elapsed_us) / 1e6 AS in_wait,
sum(port_full_elapsed_us) / 1e6 AS out_wait
FROM system.processors_profile_log
WHERE query_id = 'd7edb6c5-d0ce-4baf-87d4-68b5721ff6d9'
GROUP BY name
HAVING elapsed > 2
ORDER BY elapsed DESC
┌─name───────────────────────────────┬─────elapsed─┬────in_wait─┬───out_wait─┐
│ ConvertingAggregatedToChunksSource │ 1367.418025 │ 0.004434 │ 4.955902 │
│ AggregatingTransform │ 646.475021 │ 138.036601 │ 35.994973 │
│ MergeTreeThread │ 126.220384 │ 0.037104 │ 647.360237 │
│ PartialSortingTransform │ 2.502141 │ 64.940476 │ 1.745577 │
└────────────────────────────────────┴─────────────┴────────────┴────────────┘