Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Response time for /mertics is more than 2mins #69

Closed
saimanoj90 opened this issue Mar 13, 2024 · 7 comments
Closed

Response time for /mertics is more than 2mins #69

saimanoj90 opened this issue Mar 13, 2024 · 7 comments

Comments

@saimanoj90
Copy link

Noticed chrony_exporter taking more than 2mins to respond with metrics.

Versions Tried: 0.9.0 and 0.8.0

Environment: x86_64 GNU/Linux
@SuperQ
Copy link
Owner

SuperQ commented Mar 13, 2024

This probably means it can't connect to chrony properly.

@saimanoj90
Copy link
Author

saimanoj90 commented Mar 13, 2024 •
edited
Loading

Thanks for the quick response, enabled debug logs, below are the same for one request, took more than 2mins, why is it making multiple requests internally?

ts=2024-03-13T19:40:15.191Z caller=sources.go:100 level=debug msg="Got 'sources' response" sources_packet=SUCCESS
ts=2024-03-13T19:40:15.191Z caller=sources.go:110 level=debug msg="Fetching source" source=0
ts=2024-03-13T19:40:15.191Z caller=sources.go:110 level=debug msg="Fetching source" source=1
ts=2024-03-13T19:40:15.191Z caller=sources.go:110 level=debug msg="Fetching source" source=2
ts=2024-03-13T19:40:15.191Z caller=sources.go:110 level=debug msg="Fetching source" source=3
ts=2024-03-13T19:40:15.191Z caller=sources.go:110 level=debug msg="Fetching source" source=4
ts=2024-03-13T19:40:15.191Z caller=sources.go:110 level=debug msg="Fetching source" source=5
ts=2024-03-13T19:40:15.191Z caller=sources.go:110 level=debug msg="Fetching source" source=6
ts=2024-03-13T19:40:15.192Z caller=sources.go:110 level=debug msg="Fetching source" source=7
ts=2024-03-13T19:40:15.475Z caller=sources.go:100 level=debug msg="Got 'sources' response" sources_packet=SUCCESS
ts=2024-03-13T19:40:15.475Z caller=sources.go:110 level=debug msg="Fetching source" source=0
ts=2024-03-13T19:40:15.475Z caller=sources.go:110 level=debug msg="Fetching source" source=1
ts=2024-03-13T19:40:15.475Z caller=sources.go:110 level=debug msg="Fetching source" source=2
ts=2024-03-13T19:40:15.475Z caller=sources.go:110 level=debug msg="Fetching source" source=3
ts=2024-03-13T19:40:15.475Z caller=sources.go:110 level=debug msg="Fetching source" source=4
ts=2024-03-13T19:40:15.475Z caller=sources.go:110 level=debug msg="Fetching source" source=5
ts=2024-03-13T19:40:15.475Z caller=sources.go:110 level=debug msg="Fetching source" source=6
ts=2024-03-13T19:40:15.475Z caller=sources.go:110 level=debug msg="Fetching source" source=7
ts=2024-03-13T19:40:45.475Z caller=sources.go:100 level=debug msg="Got 'sources' response" sources_packet=SUCCESS
ts=2024-03-13T19:40:45.475Z caller=sources.go:110 level=debug msg="Fetching source" source=0
ts=2024-03-13T19:40:45.475Z caller=sources.go:110 level=debug msg="Fetching source" source=1
ts=2024-03-13T19:40:45.475Z caller=sources.go:110 level=debug msg="Fetching source" source=2
ts=2024-03-13T19:40:45.475Z caller=sources.go:110 level=debug msg="Fetching source" source=3
ts=2024-03-13T19:40:45.475Z caller=sources.go:110 level=debug msg="Fetching source" source=4
ts=2024-03-13T19:40:45.475Z caller=sources.go:110 level=debug msg="Fetching source" source=5
ts=2024-03-13T19:40:45.475Z caller=sources.go:110 level=debug msg="Fetching source" source=6
ts=2024-03-13T19:40:45.475Z caller=sources.go:110 level=debug msg="Fetching source" source=7
ts=2024-03-13T19:41:15.475Z caller=sources.go:100 level=debug msg="Got 'sources' response" sources_packet=SUCCESS
ts=2024-03-13T19:41:15.475Z caller=sources.go:110 level=debug msg="Fetching source" source=0
ts=2024-03-13T19:41:15.475Z caller=sources.go:110 level=debug msg="Fetching source" source=1
ts=2024-03-13T19:41:15.475Z caller=sources.go:110 level=debug msg="Fetching source" source=2
ts=2024-03-13T19:41:15.475Z caller=sources.go:110 level=debug msg="Fetching source" source=3
ts=2024-03-13T19:41:15.475Z caller=sources.go:110 level=debug msg="Fetching source" source=4
ts=2024-03-13T19:41:15.475Z caller=sources.go:110 level=debug msg="Fetching source" source=5
ts=2024-03-13T19:41:15.475Z caller=sources.go:110 level=debug msg="Fetching source" source=6
ts=2024-03-13T19:41:15.475Z caller=sources.go:110 level=debug msg="Fetching source" source=7
ts=2024-03-13T19:41:45.475Z caller=sources.go:100 level=debug msg="Got 'sources' response" sources_packet=SUCCESS
ts=2024-03-13T19:41:45.475Z caller=sources.go:110 level=debug msg="Fetching source" source=0
ts=2024-03-13T19:41:45.475Z caller=sources.go:110 level=debug msg="Fetching source" source=1
ts=2024-03-13T19:41:45.475Z caller=sources.go:110 level=debug msg="Fetching source" source=2
ts=2024-03-13T19:41:45.475Z caller=sources.go:110 level=debug msg="Fetching source" source=3
ts=2024-03-13T19:41:45.475Z caller=sources.go:110 level=debug msg="Fetching source" source=4
ts=2024-03-13T19:41:45.475Z caller=sources.go:110 level=debug msg="Fetching source" source=5
ts=2024-03-13T19:41:45.476Z caller=sources.go:110 level=debug msg="Fetching source" source=6
ts=2024-03-13T19:41:45.476Z caller=sources.go:110 level=debug msg="Fetching source" source=7
ts=2024-03-13T19:42:15.475Z caller=sources.go:100 level=debug msg="Got 'sources' response" sources_packet=SUCCESS
ts=2024-03-13T19:42:15.475Z caller=sources.go:110 level=debug msg="Fetching source" source=0
ts=2024-03-13T19:42:15.475Z caller=sources.go:110 level=debug msg="Fetching source" source=1
ts=2024-03-13T19:42:15.475Z caller=sources.go:110 level=debug msg="Fetching source" source=2
ts=2024-03-13T19:42:15.475Z caller=sources.go:110 level=debug msg="Fetching source" source=3
ts=2024-03-13T19:42:15.475Z caller=sources.go:110 level=debug msg="Fetching source" source=4
ts=2024-03-13T19:42:15.475Z caller=sources.go:110 level=debug msg="Fetching source" source=5
ts=2024-03-13T19:42:15.475Z caller=sources.go:110 level=debug msg="Fetching source" source=6
ts=2024-03-13T19:42:15.475Z caller=sources.go:110 level=debug msg="Fetching source" source=7
ts=2024-03-13T19:42:25.508Z caller=tracking.go:185 level=debug msg="Got 'tracking' response" tracking_packet=SUCCESS
ts=2024-03-13T19:42:25.508Z caller=tracking.go:195 level=debug msg="Tracking Last Offset" offset=0
ts=2024-03-13T19:42:25.509Z caller=tracking.go:198 level=debug msg="Tracking Ref Time" ref_time=1970-01-01T00:00:00Z
ts=2024-03-13T19:42:25.509Z caller=tracking.go:201 level=debug msg="Tracking System Time" system_time=9.538860368252244e-09
ts=2024-03-13T19:42:25.509Z caller=tracking.go:208 level=debug msg="Tracking is remote" bool_value=1
ts=2024-03-13T19:42:25.509Z caller=tracking.go:211 level=debug msg="Tracking RMS Offset" rms_offset=0
ts=2024-03-13T19:42:25.509Z caller=tracking.go:214 level=debug msg="Tracking Root delay" root_delay=1
ts=2024-03-13T19:42:25.509Z caller=tracking.go:217 level=debug msg="Tracking Root dispersion" root_dispersion=1
ts=2024-03-13T19:42:25.509Z caller=tracking.go:220 level=debug msg="Tracking Frequency" frequency=-12.788150787353516
ts=2024-03-13T19:42:25.509Z caller=tracking.go:223 level=debug msg="Tracking Residual Frequency" residual_frequency=0
ts=2024-03-13T19:42:25.509Z caller=tracking.go:226 level=debug msg="Tracking Skew" skew=0
ts=2024-03-13T19:42:25.509Z caller=tracking.go:229 level=debug msg="Tracking Last Update Interval" update_interval=0
ts=2024-03-13T19:42:25.509Z caller=tracking.go:232 level=debug msg="Tracking Stratum" stratum=0
ts=2024-03-13T19:42:44.547Z caller=tracking.go:185 level=debug msg="Got 'tracking' response" tracking_packet=SUCCESS
ts=2024-03-13T19:42:44.547Z caller=tracking.go:185 level=debug msg="Got 'tracking' response" tracking_packet=SUCCESS
ts=2024-03-13T19:42:44.548Z caller=tracking.go:195 level=debug msg="Tracking Last Offset" offset=0
ts=2024-03-13T19:42:44.548Z caller=tracking.go:198 level=debug msg="Tracking Ref Time" ref_time=1970-01-01T00:00:00Z
ts=2024-03-13T19:42:44.548Z caller=tracking.go:195 level=debug msg="Tracking Last Offset" offset=0
ts=2024-03-13T19:42:44.548Z caller=tracking.go:201 level=debug msg="Tracking System Time" system_time=9.615535923046536e-09
ts=2024-03-13T19:42:44.548Z caller=tracking.go:208 level=debug msg="Tracking is remote" bool_value=1
ts=2024-03-13T19:42:44.548Z caller=tracking.go:211 level=debug msg="Tracking RMS Offset" rms_offset=0
ts=2024-03-13T19:42:44.548Z caller=tracking.go:214 level=debug msg="Tracking Root delay" root_delay=1
ts=2024-03-13T19:42:44.548Z caller=tracking.go:198 level=debug msg="Tracking Ref Time" ref_time=1970-01-01T00:00:00Z
ts=2024-03-13T19:42:44.548Z caller=tracking.go:217 level=debug msg="Tracking Root dispersion" root_dispersion=1
ts=2024-03-13T19:42:44.548Z caller=tracking.go:220 level=debug msg="Tracking Frequency" frequency=-12.788150787353516
ts=2024-03-13T19:42:44.548Z caller=tracking.go:223 level=debug msg="Tracking Residual Frequency" residual_frequency=0
ts=2024-03-13T19:42:44.548Z caller=tracking.go:201 level=debug msg="Tracking System Time" system_time=9.615535034868117e-09
ts=2024-03-13T19:42:44.548Z caller=tracking.go:226 level=debug msg="Tracking Skew" skew=0
ts=2024-03-13T19:42:44.548Z caller=tracking.go:229 level=debug msg="Tracking Last Update Interval" update_interval=0
ts=2024-03-13T19:42:44.548Z caller=tracking.go:232 level=debug msg="Tracking Stratum" stratum=0
ts=2024-03-13T19:42:44.548Z caller=tracking.go:208 level=debug msg="Tracking is remote" bool_value=1
ts=2024-03-13T19:42:44.548Z caller=tracking.go:211 level=debug msg="Tracking RMS Offset" rms_offset=0
ts=2024-03-13T19:42:44.548Z caller=tracking.go:214 level=debug msg="Tracking Root delay" root_delay=1
ts=2024-03-13T19:42:44.548Z caller=tracking.go:217 level=debug msg="Tracking Root dispersion" root_dispersion=1
ts=2024-03-13T19:42:44.548Z caller=tracking.go:220 level=debug msg="Tracking Frequency" frequency=-12.788150787353516
ts=2024-03-13T19:42:44.548Z caller=tracking.go:223 level=debug msg="Tracking Residual Frequency" residual_frequency=0
ts=2024-03-13T19:42:44.548Z caller=tracking.go:226 level=debug msg="Tracking Skew" skew=0
ts=2024-03-13T19:42:44.548Z caller=tracking.go:229 level=debug msg="Tracking Last Update Interval" update_interval=0
ts=2024-03-13T19:42:44.548Z caller=tracking.go:232 level=debug msg="Tracking Stratum" stratum=0
ts=2024-03-13T19:42:45.475Z caller=sources.go:100 level=debug msg="Got 'sources' response" sources_packet=SUCCESS
ts=2024-03-13T19:42:45.475Z caller=sources.go:110 level=debug msg="Fetching source" source=0
ts=2024-03-13T19:42:45.476Z caller=sources.go:110 level=debug msg="Fetching source" source=1
ts=2024-03-13T19:42:45.476Z caller=sources.go:110 level=debug msg="Fetching source" source=2
ts=2024-03-13T19:42:45.476Z caller=sources.go:110 level=debug msg="Fetching source" source=3
ts=2024-03-13T19:42:45.476Z caller=sources.go:110 level=debug msg="Fetching source" source=4
ts=2024-03-13T19:42:45.476Z caller=sources.go:110 level=debug msg="Fetching source" source=5
ts=2024-03-13T19:42:45.476Z caller=sources.go:110 level=debug msg="Fetching source" source=6
ts=2024-03-13T19:42:45.476Z caller=sources.go:110 level=debug msg="Fetching source" source=7
ts=2024-03-13T19:43:15.475Z caller=sources.go:100 level=debug msg="Got 'sources' response" sources_packet=SUCCESS
ts=2024-03-13T19:43:15.475Z caller=sources.go:110 level=debug msg="Fetching source" source=0
ts=2024-03-13T19:43:15.475Z caller=sources.go:110 level=debug msg="Fetching source" source=1
ts=2024-03-13T19:43:15.476Z caller=sources.go:110 level=debug msg="Fetching source" source=2
ts=2024-03-13T19:43:15.476Z caller=sources.go:110 level=debug msg="Fetching source" source=3
ts=2024-03-13T19:43:15.476Z caller=sources.go:110 level=debug msg="Fetching source" source=4
ts=2024-03-13T19:43:15.476Z caller=sources.go:110 level=debug msg="Fetching source" source=5
ts=2024-03-13T19:43:15.476Z caller=sources.go:110 level=debug msg="Fetching source" source=6
ts=2024-03-13T19:43:15.476Z caller=sources.go:110 level=debug msg="Fetching source" source=7

@SuperQ
Copy link
Owner

SuperQ commented Mar 14, 2024

I think you are seeing multiple scrape requests interleaved.

As for slowness, my first guess is DNS lookups for you are very slow. Try --no-collector.dns-lookups.

@SuperQ SuperQ mentioned this issue Mar 14, 2024
Merged
@SuperQ
Copy link
Owner

SuperQ commented Mar 14, 2024

Give v0.9.1 a try.

@saimanoj90
Copy link
Author

@SuperQ , Thank you so much for the superfast patch release. Sorry for the delay, bit occupied.
As you correctly stated, they were not multiple internal calls but multiple scrape requests interleaved.
Also for the slowness, my DNS lookups are very slow.

ts=2024-03-17T10:44:46.618Z caller=collector.go:147 level=debug scrape_id=413 msg="Scrape starting"
ts=2024-03-17T10:44:46.619Z caller=sources.go:98 level=debug scrape_id=413 msg="Got 'sources' response" sources_packet=SUCCESS
ts=2024-03-17T10:44:46.619Z caller=sources.go:108 level=debug scrape_id=413 msg="Fetching source" source=0
ts=2024-03-17T10:44:46.619Z caller=sources.go:108 level=debug scrape_id=413 msg="Fetching source" source=1
ts=2024-03-17T10:44:46.619Z caller=sources.go:108 level=debug scrape_id=413 msg="Fetching source" source=2
ts=2024-03-17T10:44:46.619Z caller=sources.go:108 level=debug scrape_id=413 msg="Fetching source" source=3
ts=2024-03-17T10:44:46.619Z caller=sources.go:108 level=debug scrape_id=413 msg="Fetching source" source=4
ts=2024-03-17T10:44:46.619Z caller=sources.go:108 level=debug scrape_id=413 msg="Fetching source" source=5
ts=2024-03-17T10:44:46.619Z caller=sources.go:108 level=debug scrape_id=413 msg="Fetching source" source=6
ts=2024-03-17T10:44:46.619Z caller=sources.go:108 level=debug scrape_id=413 msg="Fetching source" source=7
ts=2024-03-17T10:45:06.637Z caller=collector.go:192 level=debug scrape_id=413 msg="DNS lookup took" seconds=20.017809495
ts=2024-03-17T10:45:26.655Z caller=collector.go:192 level=debug scrape_id=413 msg="DNS lookup took" seconds=20.017554872
ts=2024-03-17T10:45:46.673Z caller=collector.go:192 level=debug scrape_id=413 msg="DNS lookup took" seconds=20.017628878
ts=2024-03-17T10:46:06.690Z caller=collector.go:192 level=debug scrape_id=413 msg="DNS lookup took" seconds=20.017616111
ts=2024-03-17T10:46:26.702Z caller=collector.go:192 level=debug scrape_id=413 msg="DNS lookup took" seconds=20.010997172
ts=2024-03-17T10:46:46.719Z caller=collector.go:192 level=debug scrape_id=413 msg="DNS lookup took" seconds=20.01770098
ts=2024-03-17T10:47:06.733Z caller=collector.go:192 level=debug scrape_id=413 msg="DNS lookup took" seconds=20.013794083
ts=2024-03-17T10:47:26.745Z caller=collector.go:192 level=debug scrape_id=413 msg="DNS lookup took" seconds=20.011823599
ts=2024-03-17T10:47:26.745Z caller=tracking.go:177 level=debug scrape_id=413 msg="Got 'tracking' response" tracking_packet=SUCCESS
ts=2024-03-17T10:47:26.745Z caller=tracking.go:187 level=debug scrape_id=413 msg="Tracking Last Offset" offset=0
ts=2024-03-17T10:47:26.745Z caller=tracking.go:190 level=debug scrape_id=413 msg="Tracking Ref Time" ref_time=1970-01-01T00:00:00Z
ts=2024-03-17T10:47:26.745Z caller=tracking.go:193 level=debug scrape_id=413 msg="Tracking System Time" system_time=3.406283966000956e-08
ts=2024-03-17T10:47:26.745Z caller=tracking.go:200 level=debug scrape_id=413 msg="Tracking is remote" bool_value=1
ts=2024-03-17T10:47:26.745Z caller=tracking.go:203 level=debug scrape_id=413 msg="Tracking RMS Offset" rms_offset=0
ts=2024-03-17T10:47:26.745Z caller=tracking.go:206 level=debug scrape_id=413 msg="Tracking Root delay" root_delay=1
ts=2024-03-17T10:47:26.745Z caller=tracking.go:209 level=debug scrape_id=413 msg="Tracking Root dispersion" root_dispersion=1
ts=2024-03-17T10:47:26.745Z caller=tracking.go:212 level=debug scrape_id=413 msg="Tracking Frequency" frequency=-12.460677146911621
ts=2024-03-17T10:47:26.746Z caller=tracking.go:215 level=debug scrape_id=413 msg="Tracking Residual Frequency" residual_frequency=0
ts=2024-03-17T10:47:26.746Z caller=tracking.go:218 level=debug scrape_id=413 msg="Tracking Skew" skew=0
ts=2024-03-17T10:47:26.746Z caller=tracking.go:221 level=debug scrape_id=413 msg="Tracking Last Update Interval" update_interval=0
ts=2024-03-17T10:47:26.746Z caller=tracking.go:224 level=debug scrape_id=413 msg="Tracking Stratum" stratum=0
ts=2024-03-17T10:47:26.746Z caller=collector.go:150 level=debug scrape_id=413 msg="Scrape completed" seconds=160.127160753

@SuperQ
Copy link
Owner

SuperQ commented Mar 17, 2024

Looks like you have a broken server somewhere. I would recommend using CoreDNS. It can provide local caching.

Either way, this doesn't look like an exporter issue.

@SuperQ SuperQ closed this as completed Mar 17, 2024
@saimanoj90
Copy link
Author

Thanks for the recommendation. Yes, either way it is not exporter issue.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@SuperQ @saimanoj90