Response time for /mertics is more than 2mins

[saimanoj90]

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]

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

[saimanoj90]

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]

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]

Give v0.9.1 a try.

[saimanoj90]

@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]

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.

[saimanoj90]

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