PMM Query Analytics - There is no query data for the selected host

Percona Monitoring and Management (PMM) PMM 1.x
#1

Hi,

I have configured on my MySql server Query analytics using

pmm-admin add mysql:queries mysql_swcolabmysql01_queries --query-source perfschema --user pmm_admin --password PASSWORD --host 192.168.142.138

Yet continue too get the message

"There is no query data for the selected host. Use the pmm-admin add command to add a monitoring service and try again. For the information, see PMM documentation."

I have followed all the recommendations in the documentation but still do not see any data on the PMM server.

On the lab server I see:

-bash-4.1$ sudo pmm-admin list
pmm-admin 1.5.3

PMM Server | 192.168.145.100 (password-protected)
Client Name | swcolabmysql01.wco.int
Client Address | 192.168.142.138
Service Manager | unix-systemv

SERVICE TYPE NAME LOCAL PORT RUNNING DATA SOURCE OPTIONS

mysql:queries mysql_swcolabmysql01_queries - YES pmm_admin:@tcp(192.168.142.138:3306) query_source=perfschema, query_examples=true
linux:metrics linux_swcolabmysql01 42000 YES -
mysql:metrics mysql_swcolabmysql01 42002 YES pmm_admin:@tcp(192.168.142.138:3306)

-bash-4.1$ sudo pmm-admin check-network –-no-emoji
PMM Network Status

Server Address | 192.168.145.100
Client Address | 192.168.142.138

  • System Time
    PMM Server | 2018-01-16 13:35:37 +0000 GMT
    PMM Client | 2018-01-16 08:35:42 -0500 EST
    PMM Client to PMM Server Time Drift | OK

  • Connection: Client --> Server

SERVER SERVICE STATUS

Consul API OK
Prometheus API OK
Query Analytics API OK

Connection duration | 1.388602ms
Request duration | 1.152622ms
Full round trip | 2.541224ms

  • Connection: Client <-- Server

SERVICE TYPE NAME REMOTE ENDPOINT STATUS HTTPS/TLS PASSWORD

linux:metrics linux_swcolabmysql01 192.168.142.138:42000 OK YES YES
mysql:metrics mysql_swcolabmysql01 192.168.142.138:42002 OK YES YES

In the log file on the lab I see (Note at 08:04 I rebooted the PMM server to see if that helped).

-bash-4.1$ cd /var/log
-bash-4.1$ ls pmm*
pmm-linux-metrics-42000.log pmm-mysql-metrics-42002.log pmm-mysql-queries-0.log
-bash-4.1$ cat pmm-mysql-queries-0.log

Version: percona-qan-agent 1.5.3

Basedir: /usr/local/percona/qan-agent

PID: 24186

API: 192.168.145.100/qan-api

UUID: 9ae8c065d53742f26ef7d654dd241c59

2018/01/15 10:53:09.823274 main.go:163: Starting agent…
2018/01/15 10:53:09.844021 main.go:331: Agent is ready
2018/01/15 10:53:09.849434 main.go:204: API is ready
2018/01/15 11:36:05.313521 main.go:359: Caught terminated signal, shutting down
2018/01/15 11:36:05.318104 main.go:385: Stopping QAN…
2018/01/15 11:36:05.320828 main.go:392: Waiting 2 seconds to flush agent log to API…
2018/01/15 11:36:07.320957 main.go:167: Agent has stopped

Version: percona-qan-agent 1.5.3

Basedir: /usr/local/percona/qan-agent

PID: 27917

API: 192.168.145.100/qan-api

UUID: 9ae8c065d53742f26ef7d654dd241c59

2018/01/15 11:36:07.489520 main.go:163: Starting agent…
2018/01/15 11:36:07.513571 main.go:331: Agent is ready
2018/01/15 11:36:07.926160 main.go:204: API is ready
2018/01/15 14:51:31.123515 WARNING data-sender Waiting for API to ack qan_1516045860022067071: read tcp 192.168.142.138:55730->192.168.145.100:80: i/o timeout
2018/01/15 14:57:48.640289 WARNING data-sender Waiting for API to ack qan_1516046220021828738: read tcp 192.168.142.138:56460->192.168.145.100:80: i/o timeout
2018/01/15 16:20:45.654272 WARNING data-sender Waiting for API to ack qan_1516051200021886586: read tcp 192.168.142.138:40972->192.168.145.100:80: i/o timeout
2018/01/15 16:51:13.010019 WARNING data-sender Waiting for API to ack qan_1516053060022859103: read tcp 192.168.142.138:45352->192.168.145.100:80: i/o timeout
2018/01/15 19:06:40.079354 WARNING data-sender Waiting for API to ack qan_1516061160413424479: read tcp 192.168.142.138:38192->192.168.145.100:80: i/o timeout
2018/01/16 08:04:28.383776 WARNING agent ws error: EOF
2018/01/16 08:04:28.384398 WARNING agent Lost connection to API, reconnecting
2018/01/16 08:04:31.385220 WARNING agent-ws websocket.Dial ws://192.168.145.100:80/qan-api/agents/9ae8c065d53742f26ef7d654dd241c59/cmd: dial tcp 192.168.145.100:80: getsockopt: connection refused
2018/01/16 08:04:31.385348 WARNING log Lost connection to API
2018/01/16 08:04:34.386904 WARNING log-ws websocket.Dial ws://192.168.145.100:80/qan-api/agents/9ae8c065d53742f26ef7d654dd241c59/log: dial tcp 192.168.145.100:80: getsockopt: connection refused
2018/01/16 08:04:38.386815 WARNING agent-ws websocket.Dial ws://192.168.145.100:80/qan-api/agents/9ae8c065d53742f26ef7d654dd241c59/cmd: dial tcp 192.168.145.100:80: getsockopt: connection refused
2018/01/16 08:04:38.636352 WARNING data-sender Cannot connect to API: websocket.Dial ws://192.168.145.100:80/qan-api/agents/9ae8c065d53742f26ef7d654dd241c59/data: dial tcp 192.168.145.100:80: getsockopt: connection refused
2018/01/16 08:04:41.388419 WARNING log-ws websocket.Dial ws://192.168.145.100:80/qan-api/agents/9ae8c065d53742f26ef7d654dd241c59/log: dial tcp 192.168.145.100:80: getsockopt: connection refused
2018/01/16 08:04:41.638030 WARNING data-sender Cannot connect to API: websocket.Dial ws://192.168.145.100:80/qan-api/agents/9ae8c065d53742f26ef7d654dd241c59/data: dial tcp 192.168.145.100:80: getsockopt: connection refused
2018/01/16 08:04:44.639667 WARNING data-sender Cannot connect to API: websocket.Dial ws://192.168.145.100:80/qan-api/agents/9ae8c065d53742f26ef7d654dd241c59/data: dial tcp 192.168.145.100:80: getsockopt: connection refused
2018/01/16 08:05:03.389336 WARNING agent-ws websocket.Dial ws://192.168.145.100:80/qan-api/agents/9ae8c065d53742f26ef7d654dd241c59/cmd: dial tcp 192.168.145.100:80: i/o timeout
2018/01/16 08:05:06.388862 WARNING log-ws websocket.Dial ws://192.168.145.100:80/qan-api/agents/9ae8c065d53742f26ef7d654dd241c59/log: dial tcp 192.168.145.100:80: i/o timeout
2018/01/16 08:05:44.389662 WARNING agent-ws websocket.Dial ws://192.168.145.100:80/qan-api/agents/9ae8c065d53742f26ef7d654dd241c59/cmd: dial tcp 192.168.145.100:80: i/o timeout
2018/01/16 08:05:47.389268 WARNING log-ws websocket.Dial ws://192.168.145.100:80/qan-api/agents/9ae8c065d53742f26ef7d654dd241c59/log: dial tcp 192.168.145.100:80: i/o timeout
2018/01/16 08:05:51.635114 WARNING data-sender Cannot connect to API: websocket.Dial ws://192.168.145.100:80/qan-api/agents/9ae8c065d53742f26ef7d654dd241c59/data: dial tcp 192.168.145.100:80: i/o timeout
2018/01/16 08:05:54.638889 WARNING data-sender Cannot connect to API: websocket.Dial ws://192.168.145.100:80/qan-api/agents/9ae8c065d53742f26ef7d654dd241c59/data: dial tcp 192.168.145.100:80: getsockopt: connection refused
2018/01/16 08:05:57.792828 WARNING data-sender Cannot connect to API: bad status
2018/01/16 08:27:01.132122 WARNING qan-analyzer-mysql-b476a926-worker Interval out of sequence: got 1, expected 1251

#2

If in mysql i run

SELECT COALESCE(SCHEMA_NAME, ‘’), COALESCE(DIGEST, ‘’), COALESCE(DIGEST_TEXT, ‘’), COUNT_STAR, SUM_TIMER_WAIT, MIN_TIMER_WAIT, AVG_TIMER_WAIT, MAX_TIMER_WAIT, SUM_LOCK_TIME, SUM_ERRORS, SUM_WARNINGS, SUM_ROWS_AFFECTED, SUM_ROWS_SENT, SUM_ROWS_EXAMINED, SUM_CREATED_TMP_DISK_TABLES, SUM_CREATED_TMP_TABLES, SUM_SELECT_FULL_JOIN, SUM_SELECT_FULL_RANGE_JOIN, SUM_SELECT_RANGE, SUM_SELECT_RANGE_CHECK, SUM_SELECT_SCAN, SUM_SORT_MERGE_PASSES, SUM_SORT_RANGE, SUM_SORT_ROWS, SUM_SORT_SCAN, SUM_NO_INDEX_USED, SUM_NO_GOOD_INDEX_USED FROM performance_schema.events_statements_summary_by_digest WHERE LAST_SEEN >= NOW() - INTERVAL 59 SECOND;

I see data exists

36 rows in set (0.01 sec)

#3

And in the data dir for the quan agent I see files being posted.

Basedir: /usr/local/percona/qan-agent

-bash-4.1$ pwd
/usr/local/percona/qan-agent/data

-bash-4.1$ ls -ltr
total 8
-rw-r–r-- 1 root root 6072 Jan 16 08:48 qan_1516110481140665389

#4

Hi,

First let me ask you - is there any reason you’re not running the agent locally but trying to get metrics and queries from remote host ?

You can get a lot more value if you can queries, OS metrics, MySQL metrics all from the same host.

Now it looks like after restart you can’t connect to API does

pmm-admin check-network –-no-emoji

Still says everything is OK ?

What does this say on server running PMM Server container:

docker exec -it pmm-server tail -100 /var/log/qan-api.log

#5

So the question is, why does the data not get to the PMM server?

#6

Does it matter if the date on the PMM server is

[root@scordbapmm01 grafana]# date
Tue Jan 16 14:01:26 UTC 2018

And the date on the MySql server is

-bash-4.1$ date
Tue Jan 16 09:01:22 EST 2018

#7

Hi,

Different time zone is OK. The time matches

  • System Time
    PMM Server | 2018-01-16 13:35:37 +0000 GMT
    PMM Client | 2018-01-16 08:35:42 -0500 EST
    PMM Client to PMM Server Time Drift | OK

One thing I’m not sure - did you restart PMM Server or PMM Client ?

You surely had problems with connection

api/agents/9ae8c065d53742f26ef7d654dd241c59/data: dial tcp 192.168.145.100:80: getsockopt: connection refused
2018/01/16 08:05:57.792828 WARNING data-sender Cannot connect to API: bad status

#8

I restarted the PMM server at 08:04 this morning.

I have tried both the performance schema and slow log methods of gathering the data with no difference in the results over the past two days.

Can you point me to the right place to look for more diagnostics on this?

BTW I am using the OVA install of the PMM server.

#9

In the slow.log of mysql I see my slow test queries, so I know it is all there.

Time: 2018-01-16T10:57:53.988778-05:00

User@Host: baasp[baasp] @ localhost [] Id: 42910283

Query_time: 0.544869 Lock_time: 0.000076 Rows_sent: 2 Rows_examined: 351049

SET timestamp=1516118273;
select * from gt where c in (‘62H08XLZV6WQP1RGOSNJJU8DV1A133VVD1TPSK6Z0TTCZMXE1N’, ‘W73J5UHK6VIRX5OO33WYSVNDOXFZDMSQ2UPSK3LBMV74S9M3BZ’) order by i;

Time: 2018-01-16T10:57:56.397153-05:00

User@Host: baasp[baasp] @ localhost [] Id: 42910283

Query_time: 0.538233 Lock_time: 0.000137 Rows_sent: 3 Rows_examined: 351049

SET timestamp=1516118276;
select * from gt where c in (‘62H08XLZV6WQP1RGOSNJJU8DV1A133VVD1TPSK6Z0TTCZMXE1N’, ‘W73J5UHK6VIRX5OO33WYSVNDOXFZDMSQ2UPSK3LBMV74S9M3BZ’, ‘E0JD0LQMMXJOFUPP48GEA0V3LCQA0W705EDCCGWXM3C4ASVNET’) order by i;

Time: 2018-01-16T10:57:59.010418-05:00

User@Host: baasp[baasp] @ localhost [] Id: 42910283

Query_time: 0.543500 Lock_time: 0.000130 Rows_sent: 2 Rows_examined: 351049

SET timestamp=1516118279;
select * from gt where c in (‘62H08XLZV6WQP1RGOSNJJU8DV1A133VVD1TPSK6Z0TTCZMXE1N’, ‘W73J5UHK6VIRX5OO33WYSVNDOXFZDMSQ2UPSK3LBMV74S9M3BZ’) order by i;

Time: 2018-01-16T10:58:01.895983-05:00

User@Host: baasp[baasp] @ localhost [] Id: 42910283

Query_time: 0.533053 Lock_time: 0.000136 Rows_sent: 3 Rows_examined: 351049

SET timestamp=1516118281;
select * from gt where c in (‘62H08XLZV6WQP1RGOSNJJU8DV1A133VVD1TPSK6Z0TTCZMXE1N’, ‘W73J5UHK6VIRX5OO33WYSVNDOXFZDMSQ2UPSK3LBMV74S9M3BZ’, ‘E0JD0LQMMXJOFUPP48GEA0V3LCQA0W705EDCCGWXM3C4ASVNET’) order by i;

#10

Update I came across anothe rpost that had some trouble shooting guidance.

https://www.percona.com/forums/questions-discussions/percona-monitoring-and-management/49720-unable-to-start-mysql-queries

so I did

systemctl status percona-qan-api
journalctl -u percona-qan-api

Below is the last part from the journalctl -u percona-qan-api output.

Jan 16 20:53:33 scordbapmm01.wco.int systemd[1]: Stopping Percona Query Analytics API…
Jan 16 20:53:33 scordbapmm01.wco.int systemd[1]: Started Percona Query Analytics API.
Jan 16 20:53:33 scordbapmm01.wco.int systemd[1]: Starting Percona Query Analytics API…
Jan 16 20:53:34 scordbapmm01.wco.int percona-qan-api[1921]: ERROR: logging before flag.Parse: I0116 20:53:34.501383 1921 logutil.go:31] log: Loading /etc/percona-qan-api.conf
Jan 16 20:53:34 scordbapmm01.wco.int percona-qan-api[1921]: ERROR: logging before flag.Parse: I0116 20:53:34.514939 1921 logutil.go:31] log: API root dir /usr/share/percona-qan-api/src/github.com/percona/
Jan 16 20:53:34 scordbapmm01.wco.int percona-qan-api[1921]: ERROR: logging before flag.Parse: I0116 20:53:34.533979 1921 logutil.go:31] log: connected to db.
Jan 16 20:53:34 scordbapmm01.wco.int percona-qan-api[1921]: INFO 2018/01/16 20:53:34 revel.go:230: Initialized Revel v0.13.1 (2016-06-06) for >= go1.4
Jan 16 20:53:34 scordbapmm01.wco.int percona-qan-api[1921]: INFO 2018/01/16 20:53:34 main.go:31: Running revel server
Jan 16 20:53:34 scordbapmm01.wco.int percona-qan-api[1921]: Listening on :9001…
Jan 16 20:53:35 scordbapmm01.wco.int percona-qan-api[1921]: INFO 2018/01/16 20:53:35 ws.go:107: [Agent.Cmd] agent_id=5 0.0.9 http://swcolabmysql01.wco.int: connected
Jan 16 20:53:58 scordbapmm01.wco.int percona-qan-api[1921]: 2018/01/16 20:53:58.620 127.0.0.1 0 265.901794ms WS /agents/9ae8c065d53742f26ef7d654dd241c59/data
Jan 16 20:55:02 scordbapmm01.wco.int percona-qan-api[1921]: 2018/01/16 20:55:02.070 127.0.0.1 200 1.617993ms GET /instances
Jan 16 20:55:02 scordbapmm01.wco.int percona-qan-api[1921]: 2018/01/16 20:55:01.621 127.0.0.1 0 482.371607ms WS /agents/9ae8c065d53742f26ef7d654dd241c59/data
Jan 16 20:55:06 scordbapmm01.wco.int percona-qan-api[1921]: 2018/01/16 20:55:06.963 127.0.0.1 200 1.553631ms GET /instances
Jan 16 20:55:10 scordbapmm01.wco.int percona-qan-api[1921]: 2018/01/16 20:55:10.287 127.0.0.1 200 1.623953ms GET /instances
Jan 16 20:55:37 scordbapmm01.wco.int percona-qan-api[1921]: 2018/01/16 20:55:37.226 127.0.0.1 200 123.842781ms GET /instances
Jan 16 20:56:05 scordbapmm01.wco.int percona-qan-api[1921]: 2018/01/16 20:56:04.627 127.0.0.1 0 1.272987083s WS /agents/9ae8c065d53742f26ef7d654dd241c59/data

it appears the MySql server is connecting. However I still see no data:(

#11

Should this file on the PMM server reflect the user credentials on the MySql agent server?

[root@scordbapmm01 ~]# cat /etc/percona-qan-api.conf
api.alias = :host
api.hostname = :host::port
api.base.ws = ws://:host::port
api.base.http = http://:host::port
api.base.path =
api.collect.path = /srv/collect_info

mysql.db = pmm
mysql.dsn = percona:percona@tcp(localhost:3306)/pmm?parseTime=true&interpolateParams=true&time_zone="%2B00%3A00"&loc=UTC

stats.env = prod
stats.rate = 1.0
statsd.server =

#12

Generally you should not need to change anything inside of OVA/Docker Manually.

In your case you see what MySQL Queries are in the Slow query log. Furthermore you see Agent is processing them and creating spool file. This file however is not being sent to PMM-Server correctly

This could mean either there is some network connection issue or there are some problems processing results and for example the “QAN API” Crashes.

The way I would approach diagnosing it would be try to remove the real production server you’re trying to add and add try to add an idle MySQL server which has no traffic. QAN agent on it will generate some light traffic and you should see such queries in QAN… we know QAN should not have issue processing this load.

I would restart the Agent on the MySQL server you’re trying to add and send me logs again. Current logs you have are a bit unconclusive… and frankly we do not have very good logging here

2018/01/16 08:05:54.638889 WARNING data-sender Cannot connect to API: websocket.Dial ws://192.168.145.100:80/qan-api/agents/9ae8c065d53742f26ef7d654dd241c59/data: dial tcp 192.168.145.100:80: getsockopt: connection refused
2018/01/16 08:05:57.792828 WARNING data-sender Cannot connect to API: bad status
2018/01/16 08:27:01.132122 WARNING qan-analyzer-mysql-b476a926-worker Interval out of sequence: got 1, expected 1251

Connection was refused but only such message is at 8:05 What did happen up to 8:27 when you got some other error ?

If you restart Agent we should see better if it was connected successfully or have some other problems for some reasons.

#13

Hi,

My bad for not being clear. The server we are working on is our lab MySql server. Any load was generated by me trying to produce something for the analyzer to see.

What I have done this morning as suggested is:

-bash-4.1$ date
Wed Jan 17 08:14:00 EST 2018
-bash-4.1$ sudo pmm-admin stop --all
OK, stopped 3 services.
-bash-4.1$ date
Wed Jan 17 08:14:34 EST 2018
-bash-4.1$ sudo pmm-admin start --all
OK, started 3 services.

-bash-4.1$ tail -n 20 pmm-mysql-queries-0.log
2018/01/16 08:05:57.792828 WARNING data-sender Cannot connect to API: bad status
2018/01/16 08:27:01.132122 WARNING qan-analyzer-mysql-b476a926-worker Interval out of sequence: got 1, expected 1251
2018/01/16 14:45:01.132163 WARNING qan-analyzer-mysql-b476a926-worker Interval out of sequence: got 1, expected 379
2018/01/16 15:53:35.011098 WARNING agent ws error: EOF
2018/01/16 15:53:35.012706 WARNING agent Lost connection to API, reconnecting
2018/01/16 15:53:35.605911 WARNING agent-ws bad status
2018/01/16 15:53:35.606035 WARNING log Lost connection to API
2018/01/16 15:53:35.608337 WARNING log-ws bad status
2018/01/17 08:14:29.780422 main.go:359: Caught terminated signal, shutting down
2018/01/17 08:14:29.781400 main.go:385: Stopping QAN…
2018/01/17 08:14:29.793910 main.go:392: Waiting 2 seconds to flush agent log to API…
2018/01/17 08:14:31.794027 main.go:167: Agent has stopped

Version: percona-qan-agent 1.5.3

Basedir: /usr/local/percona/qan-agent

PID: 21428

API: 192.168.145.100/qan-api

UUID: 9ae8c065d53742f26ef7d654dd241c59

2018/01/17 08:14:45.414812 main.go:163: Starting agent…
2018/01/17 08:14:45.428166 main.go:331: Agent is ready
2018/01/17 08:14:45.506450 main.go:204: API is ready

That is all that is in the file at this point. I will check again in an hour or so to see if there is any other entries.

In the afternoon I can try to add a different server to validate if that is a factor.

My Telecomm admin assures me that currently I am setup TCP ports any to any between the PMM server and the agent server in both directions.

#14

Good news.

We have failure in the log file

Version: percona-qan-agent 1.5.3

Basedir: /usr/local/percona/qan-agent

PID: 21428

API: 192.168.145.100/qan-api

UUID: 9ae8c065d53742f26ef7d654dd241c59

2018/01/17 08:14:45.414812 main.go:163: Starting agent…
2018/01/17 08:14:45.428166 main.go:331: Agent is ready
2018/01/17 08:14:45.506450 main.go:204: API is ready
2018/01/17 08:38:59.841232 WARNING data-sender Waiting for API to ack qan_1516196280033895545: read tcp 192.168.142.138:41772->192.168.145.100:80: i/o timeout
2018/01/17 08:39:09.403524 WARNING data-sender Waiting for API to ack qan_1516196280033895545: read tcp 192.168.142.138:41794->192.168.145.100:80: i/o timeout
2018/01/17 08:59:59.754027 WARNING data-sender Waiting for API to ack qan_1516197540033903673: read tcp 192.168.142.138:45934->192.168.145.100:80: i/o timeout
2018/01/17 09:00:08.420087 WARNING data-sender Waiting for API to ack qan_1516197540033903673: read tcp 192.168.142.138:45952->192.168.145.100:80: i/o timeout

So what does this mean?

#15

For anyone who has a similar problem Peter & Andrii were able to point out the issue to me and it is now corrected.

My issue was that I had created the query analytics registration using the service name mysql_swcolabmysql02_query

sudo pmm-admin add mysql:queries mysql_swcolabmysql02_query --query-source perfschema --user pmm_admin --password PASSWORD --host ###.###.###.###

Due to a current limitation of PMM it should have been

sudo pmm-admin add mysql:queries mysql_swcolabmysql02 --query-source perfschema --user pmm_admin --password PASSWORD --host ###.###.###.###

The service name in 1.5.3 must at this time match that used by mysql:metrics

sudo pmm-admin add mysql:metrics mysql_swcolabmysql02 --user pmm_admin --password PASSWORD --host ###.###.###.###

To correct I just did

sudo pmm-admin rm mysql:queries mysql_swcolabmysql02_query

Then

sudo pmm-admin add mysql:queries mysql_swcolabmysql02 --query-source perfschema --user pmm_admin --password PASSWORD --host ###.###.###.###

A few minutes later I began to see the query analytics in PMM.

Thanks Andrii & Peter

:slight_smile:

MySQL, InnoDB, MariaDB and MongoDB are trademarks of their respective owners.
Copyright © 2006 - 2021 Percona LLC. All rights reserved.