# What exactly does m\_query\_time\_cnt mean?

**URL:** <https://forums.percona.com/t/what-exactly-does-m-query-time-cnt-mean/12858>\
**Category:** PMM 2.x\
**Tags:** pmm\
**Created:** [November 4, 2021, 4:51am UTC](https://forums.percona.com/t/what-exactly-does-m-query-time-cnt-mean/12858 "2021-11-04T04:51:45Z")\
**Posts on this page:** 11\
**Page:** 1

<div class="post-metadata">

**Author:** ![Fan](https://sea1.discourse-cdn.com/flex019/user_avatar/forums.percona.com/fan/32/40_2.png) [@Fan](https://forums.percona.com/u/Fan)\
**Post date:** [November 4, 2021, 4:51am UTC](https://forums.percona.com/t/what-exactly-does-m-query-time-cnt-mean/12858/1 "2021-11-04T04:51:45Z")

</div>

I’m a bit confused about the meaning of m\_query\_time\_cnt:  
`m_query_time_cnt` Float32 COMMENT ‘The statement execution time in seconds was met.’,

At first I thought that m\_query\_time\_cnt and num\_queries were the same, but I found out that they are not

In this [blog](https://www.percona.com/blog/2020/03/30/advanced-query-analysis-in-percona-monitoring-and-management-with-direct-clickhouse-access/), there is a sql statement to query the average execution time:

```sql
# Average Query Execution Time for Last 6 hours 
 
select avg(m_query_time_sum/m_query_time_cnt) from metrics where period_start>subtractHours(now(),6);

```

In practice, however, this result does not appear to be correct

```sql
SELECT avg(m_query_time_sum / m_query_time_cnt)
FROM metrics
WHERE (period_start >= formatDateTime(yesterday() - 1, '%Y-%m-%d 16:00:00')) AND (period_start < formatDateTime(today() - 1, '%Y-%m-%d 16:00:00')) AND (queryid = '743A2DB74D4CE96F')

Query id: 5ce4af64-4279-4879-bc66-290a84b3c5b5

┌─avg(divide(m_query_time_sum, m_query_time_cnt))─┐
│ 75.04540252685547 │
└─────────────────────────────────────────────────┘

```

I think the correct sql is

```sql
SELECT sum(m_query_time_sum) / sum(num_queries)
FROM metrics
WHERE (period_start >= formatDateTime(yesterday() - 1, '%Y-%m-%d 16:00:00')) AND (period_start < formatDateTime(today() - 1, '%Y-%m-%d 16:00:00')) AND (queryid = '743A2DB74D4CE96F')

Query id: 29eef184-dda9-4729-ace5-6909598c3d91

┌─divide(sum(m_query_time_sum), sum(num_queries))─┐
│ 0.7504540252685546 │
└─────────────────────────────────────────────────┘

```

This is also true via qan-api

 ![image](https://us1.discourse-cdn.com/flex019/uploads/percona1/original/2X/6/67f0e8272a7832d10549e3d8cfa68a54d9423574.png)

```sql
SELECT
    num_queries,
    m_query_time_cnt,
    m_query_time_sum,
    m_query_time_min,
    m_query_time_max,
    m_query_time_p99
FROM metrics
WHERE queryid = '743A2DB74D4CE96F'
ORDER BY period_start DESC
LIMIT 1

Query id: 4fa1b6e4-9c70-4828-b2b9-9e0976e19d1b

Row 1:
──────
num_queries: 100
m_query_time_cnt: 1
m_query_time_sum: 71.1733
m_query_time_min: 0.711733
m_query_time_max: 0.711733
m_query_time_p99: 0.711733

```

The above query also shows that query\_time\_avg should be equal to query\_time\_sum/num\_queries

So, I’m a bit confused about the meaning of m\_query\_time\_cnt, what does it do and how is it calculated?

~~2021.11.08~~  
~~It seems that m\_xx\_xx\_cnt represents the number of times the statement appears in the slow query log within this collection window~~

~~So, using the above result as an example, m\_query\_time\_cnt=1, means that this query statement appeared in the slow query log once during this collection period, and then with my parameter log\_slow\_rate\_limit=100, so num\_queries= m\_query\_time\_cnt\* log\_ slow\_rate\_limit=1\*100=100. Is that right?~~

The Dashboard RED Method for MySQL Queries - Designed for PMM2 has a panel

 ![image](https://us1.discourse-cdn.com/flex019/uploads/percona1/original/2X/0/0f1039e55342070e23d17b9b1a2f6f59ac5ee7ae.png)

```auto
SELECT
    num_queries,
    m_query_time_cnt,
    m_query_time_sum,
    m_query_time_min,
    m_query_time_max,
    m_query_time_p99
FROM pmm.metrics
WHERE (period_start = '2021-11-09 05:02:00') AND (period_start < '2021-11-09 16:00:00') AND (1 = 1) AND (service_type = 'mysql') AND (queryid = 'A3F4BE1B0BE03335')

Query id: 6e8a09d7-da0e-4927-ba1f-ca4d503acb0a

Row 1:
──────
num_queries: 14400
m_query_time_cnt: 144
m_query_time_sum: 2.1127
m_query_time_min: 0.000103
m_query_time_max: 0.000222
m_query_time_p99: 0.000212

1 rows in set. Elapsed: 0.008 sec. Processed 8.19 thousand rows, 457.58 KB (1.03 million rows/s., 57.63 MB/s.)

This query returns only one row

SELECT sum(m_query_time_sum) / sum(m_query_time_cnt)
FROM pmm.metrics
WHERE (period_start = '2021-11-09 05:02:00') AND (1 = 1) AND (service_type = 'mysql') AND (queryid = 'A3F4BE1B0BE03335')

Query id: 333f32e1-dab2-4839-adaf-579c774409df

┌─divide(sum(m_query_time_sum), sum(m_query_time_cnt))─┐
│ 0.014671527677112155 │
└──────────────────────────────────────────────────────┘
1 rows in set. Elapsed: 0.008 sec. Processed 8.19 thousand rows, 326.51 KB (983.38 thousand rows/s., 39.20 MB/s.)

```

sum(m\_query\_time\_sum) / sum(m\_query\_time\_cnt)= 0.014671527677112155

0.014671527677112155 \> (m\_query\_time\_max = 0.000222)  
why?

---

<div class="post-metadata">

**Author:** ![Fan](https://sea1.discourse-cdn.com/flex019/user_avatar/forums.percona.com/fan/32/40_2.png) [@Fan](https://forums.percona.com/u/Fan)\
**Post date:** [November 11, 2021, 5:37am UTC](https://forums.percona.com/t/what-exactly-does-m-query-time-cnt-mean/12858/2 "2021-11-11T05:37:17Z")

</div>

At first I thought that m\_xx\_xx\_cnt represents the number of times the statement appears in the slow query log within this collection window

So, with my parameter log\_slow\_rate\_limit=100, num\_queries= m\_query\_time\_cnt \* log\_ slow\_rate\_limit=1\*100=100.

But I find it doesn’t seem that way either

```auto
SELECT
    queryid,
    num_queries,
    m_query_time_cnt,
    m_query_time_sum,
    m_query_time_min,
    m_query_time_max,
    m_query_time_p99
FROM pmm.metrics
WHERE (queryid = '25924BD87338F559') AND (period_start = '2021-11-05 16:00:00') AND (period_start < '2021-11-09 16:00:00')

Query id: bfccd505-e0a6-439e-a5b9-ff474abac76a

┌─queryid──────────┬─num_queries─┬─m_query_time_cnt─┬─m_query_time_sum─┬─m_query_time_min─┬─m_query_time_max─┬─m_query_time_p99─┐
│ 25924BD87338F559 │ 3600 │ 36 │ 0.9135 │ 0.000171 │ 0.000753 │ 0.000753 │
│ 25924BD87338F559 │ 3101 │ 32 │ 2.234573 │ 0.000219 │ 1.212773 │ 1.212773 │
│ 25924BD87338F559 │ 6301 │ 64 │ 4.29576 │ 0.000194 │ 1.76006 │ 1.76006 │
└──────────────────┴─────────────┴──────────────────┴──────────────────┴──────────────────┴──────────────────┴──────────────────┘

3 rows in set. Elapsed: 0.007 sec. Processed 8.19 thousand rows, 237.94 KB (1.16 million rows/s., 33.57 MB/s.)

```

num\_queries, m\_query\_time\_cnt  
3101, 32  
6301, 64

---

<div class="post-metadata">

**Author:** ![Roma\_Novikov](https://sea1.discourse-cdn.com/flex019/user_avatar/forums.percona.com/roma_novikov/32/1161_2.png) [@Roma\_Novikov](https://forums.percona.com/u/Roma_Novikov)\
**Post date:** [November 19, 2021, 9:18am UTC](https://forums.percona.com/t/what-exactly-does-m-query-time-cnt-mean/12858/3 "2021-11-19T09:18:22Z")

</div>

Hi @Fan  
you correct re

> [@Fan](#):
>
> num\_queries, m\_query\_time\_cnt

num\_queries - is a real number of queries (calculated with log\_slow\_rate\_limit)  
and m\_query\_time\_cnt - “How many times the metric appeared”  
It’s not exactly 100 times the difference in your case because of roundings in intervals.  
We need to review the blog post and revisit the implementations and fields usage to decrease confusion.

---

<div class="post-metadata">

**Author:** ![Fan](https://sea1.discourse-cdn.com/flex019/user_avatar/forums.percona.com/fan/32/40_2.png) [@Fan](https://forums.percona.com/u/Fan)\
**Post date:** [November 19, 2021, 9:28am UTC](https://forums.percona.com/t/what-exactly-does-m-query-time-cnt-mean/12858/4 "2021-11-19T09:28:43Z")

</div>

Thank you @Roma_Novikov, i get it

---

<div class="post-metadata">

**Author:** ![Fan](https://sea1.discourse-cdn.com/flex019/user_avatar/forums.percona.com/fan/32/40_2.png) [@Fan](https://forums.percona.com/u/Fan)\
**Post date:** [April 7, 2022, 6:01am UTC](https://forums.percona.com/t/what-exactly-does-m-query-time-cnt-mean/12858/5 "2022-04-07T06:01:04Z")

</div>

So is the sql in red dashboard and the sql in the blog actually correct, and if not, has it been corrected?

---

<div class="post-metadata">

**Author:** ![Fan](https://sea1.discourse-cdn.com/flex019/user_avatar/forums.percona.com/fan/32/40_2.png) [@Fan](https://forums.percona.com/u/Fan)\
**Post date:** [September 14, 2022, 7:11am UTC](https://forums.percona.com/t/what-exactly-does-m-query-time-cnt-mean/12858/7 "2022-09-14T07:11:39Z")

</div>

still waiting for your answer.

 ![image](https://us1.discourse-cdn.com/flex019/uploads/percona1/original/2X/d/d628c7be590af858a2e6b897335b377bef1d96bd.png)  
Using m\_query\_time\_sum/m\_query\_time\_cnt to calc Latency is aboslutely wrong. This [blog](https://www.percona.com/blog/2020/03/30/advanced-query-analysis-in-percona-monitoring-and-management-with-direct-clickhouse-access/) remains uncorrected.

---

<div class="post-metadata">

**Author:** ![Peter](https://sea1.discourse-cdn.com/flex019/user_avatar/forums.percona.com/peter/32/2_2.png) [@Peter](https://forums.percona.com/u/Peter)\
**Post date:** [September 19, 2022, 12:08pm UTC](https://forums.percona.com/t/what-exactly-does-m-query-time-cnt-mean/12858/8 "2022-09-19T12:08:39Z")

</div>

I’m wondering how do you get m\_query\_time\_cnt=1 in your case where num\_queries=100 This is the issue.

Generally m\_query\_time\_cnt should be equal to num\_queries as ALL queries should provide query\_time metric.

I am using metric specific count instead of num\_queries for consistency - as to compute avg value for any metric you can divide SUM of that metric by number of queries for which this metric was reported.

---

<div class="post-metadata">

**Author:** ![Fan](https://sea1.discourse-cdn.com/flex019/user_avatar/forums.percona.com/fan/32/40_2.png) [@Fan](https://forums.percona.com/u/Fan)\
**Post date:** [September 19, 2022, 12:41pm UTC](https://forums.percona.com/t/what-exactly-does-m-query-time-cnt-mean/12858/9 "2022-09-19T12:41:28Z")

</div>

we use Percona 5.7

```auto
# SLOW LOGGING #
slow_query_log_file = {{ mysql_dir }}/logs/slow.log
slow_query_log = {{ slow_query_log|default('ON') }}
long_query_time = {{ long_query_time|default(0) }}
log_slow_rate_limit = {{ log_slow_rate_limit|default(100) }}
log_slow_rate_type = {{ log_slow_rate_type|default('query') }}
log_slow_verbosity = {{ log_slow_verbosity|default('full') }}
log_slow_admin_statements = {{ log_slow_admin_statements|default('ON') }}
log_slow_slave_statements = {{ log_slow_slave_statements|default('ON') }}
slow_query_log_always_write_time = {{ slow_query_log_always_write_time|default(1) }}
slow_query_log_use_global_control = {{ slow_query_log_use_global_control|default('all') }}

```

```auto
pmm-admin add mysql --disable-collectors="{{ ','.join(mysql_disable_collectors) }}" --query-source=slowlog --username={{ pmm_user }} --password={{ pmm_password }} --size-slow-logs=1GiB --environment=${env} --cluster={{ cmdb_cluster_name }} --replication-set={{ cmdb_cluster_name }} --custom-labels="region=${region},env=${env},ha_type=MGR" $HOSTNAME'_{{ mysql_port }}' 127.0.0.1:{{ mysql_port }}

```

it seems like that num\_queries = m\_query\_time\_cnt\*log\_slow\_rate\_limit

---

<div class="post-metadata">

**Author:** ![Peter](https://sea1.discourse-cdn.com/flex019/user_avatar/forums.percona.com/peter/32/2_2.png) [@Peter](https://forums.percona.com/u/Peter)\
**Post date:** [September 19, 2022, 12:44pm UTC](https://forums.percona.com/t/what-exactly-does-m-query-time-cnt-mean/12858/10 "2022-09-19T12:44:35Z")

</div>

Right. It could be handling sampling got broken. I appreciate if you can file a bug report!

---

<div class="post-metadata">

**Author:** ![Fan](https://sea1.discourse-cdn.com/flex019/user_avatar/forums.percona.com/fan/32/40_2.png) [@Fan](https://forums.percona.com/u/Fan)\
**Post date:** [September 19, 2022, 1:32pm UTC](https://forums.percona.com/t/what-exactly-does-m-query-time-cnt-mean/12858/11 "2022-09-19T13:32:05Z")

</div>

> [@Fan](#):
>
> log\_slow\_rate\_limit

```auto
	// How many times query_time was found.
	MQueryTimeCnt float32 `protobuf:"fixed32,19,opt,name=m_query_time_cnt,json=mQueryTimeCnt,proto3" json:"m_query_time_cnt,omitempty"`

```

MQueryTimeCnt is the number of times Query\_time was found in the slow log

```auto
# Time: 2022-07-19T11:06:04.333060+08:00
# User@Host: pmm[pmm] @ [127.0.0.1] Id: 44844658
# Schema: Last_errno: 1054 Killed: 0
# Query_time: 0.000131 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0 Rows_affected: 0
# Bytes_sent: 68 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
# QC_Hit: No Full_scan: No Full_join: No Tmp_table: No Tmp_table_on_disk: No
# Filesort: No Filesort_on_disk: No Merge_passes: 0
# No InnoDB statistics available for this query
# Log_slow_rate_type: query Log_slow_rate_limit: 100

```

so m\_query\_time\_cnt=1 is fine

```auto
			case smv[1] == "Log_slow_rate_limit":
				val, _ := strconv.ParseUint(smv[2], 10, 64)
				p.event.RateLimit = uint(val)

```

```auto
NumQueries: float32(v.TotalQueries),
c.TotalQueries = (c.TotalQueries * rateLimit) + c.outliers

```

So, it looks like m\_query\_time\_cnt and num\_queries are expressing different meanings, and it is normal that they are not equal, unless you use the default value of the [parameter](https://docs.percona.com/percona-server/5.7/diagnostics/slow_extended.html#log-slow-rate-limit)

> I am using metric specific count instead of num\_queries for consistency - as to compute avg value for any metric you can divide SUM of that metric by number of queries for which this metric was reported.

All I can say is, maybe at the beginning of the design, you wanted it to look like this, but that’s not how it’s written in the code. Which design should prevail is something you need to consider internally, but it is clear that the query in the RED dashboard is problematic at this point

As a user, when our company’s R&D said that there was a problem with RED’s query time, I had to go and change it to the correct one, and then ask a question in the forum to see if it was really wrong, and if so, suggest that someone with editing rights correct the blog.

---

<div class="post-metadata">

**Author:** ![Peter](https://sea1.discourse-cdn.com/flex019/user_avatar/forums.percona.com/peter/32/2_2.png) [@Peter](https://forums.percona.com/u/Peter)\
**Post date:** [September 19, 2022, 3:40pm UTC](https://forums.percona.com/t/what-exactly-does-m-query-time-cnt-mean/12858/12 "2022-09-19T15:40:09Z")

</div>

Thank you.

We will investigate. I’m just explaining here what is design and what is the bug.

The goal is what sampling (setting low\_slow\_slave\_limit) should still represent data as close as possible to the actual load on the system. It does not only applies to number of queries but for example to network traffic, CPU used etc.

Might be it indeed was implemented differently when we also need to make sure to update documentation