{"action":"created","issue":{"url":"https://api.github.com/repos/martinlindhe/wmi_exporter/issues/89","repository_url":"https://api.github.com/repos/martinlindhe/wmi_exporter","labels_url":"https://api.github.com/repos/martinlindhe/wmi_exporter/issues/89/labels{/name}","comments_url":"https://api.github.com/repos/martinlindhe/wmi_exporter/issues/89/comments","events_url":"https://api.github.com/repos/martinlindhe/wmi_exporter/issues/89/events","html_url":"https://github.com/martinlindhe/wmi_exporter/issues/89","id":240246034,"number":89,"title":"CPU collector blocks every ~17 minutes on call to wmi.Query","user":{"login":"higels","id":1182646,"avatar_url":"https://avatars0.githubusercontent.com/u/1182646?v=4","gravatar_id":"","url":"https://api.github.com/users/higels","html_url":"https://github.com/higels","followers_url":"https://api.github.com/users/higels/followers","following_url":"https://api.github.com/users/higels/following{/other_user}","gists_url":"https://api.github.com/users/higels/gists{/gist_id}","starred_url":"https://api.github.com/users/higels/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/higels/subscriptions","organizations_url":"https://api.github.com/users/higels/orgs","repos_url":"https://api.github.com/users/higels/repos","events_url":"https://api.github.com/users/higels/events{/privacy}","received_events_url":"https://api.github.com/users/higels/received_events","type":"User","site_admin":false},"labels":[],"state":"closed","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":23,"created_at":"2017-07-03T19:03:28Z","updated_at":"2018-02-16T09:41:31Z","closed_at":"2017-07-12T11:56:21Z","author_association":"NONE","body":"We've deployed the wmi-exporter on a number of our Windows systems running Server 2012r2 standard. This was a version built several months ago with Go 1.8.\r\n\r\nThese systems typically push 20-30 Gbps of traffic and have 24 hyperthreads. There is generally plenty of room on half of these threads.\r\n\r\nHaving deployed the exporter, we observed that every 17-18 minutes (independent of when the exporter was started), the traffic being served by them would drop significantly for roughly 120 seconds and CPU consumption on one or two cores would spike. The \"WMI Provider Host\" would also increase in CPU utilisation during this time.\r\n\r\nKilling the exporter did not cause the load to drop off immediately.\r\n\r\nWe also noticed that calls to the exporter would block during this time.\r\n\r\nWe set GOMAXPROCS to 2, to see if there was any concurrency issues that might be overloading WMI, but that didn't improve matters.\r\n\r\nWe built a new version from master on Friday June 30th with Go 1.8.1. The issue persisted.\r\n\r\nWe started to disable collectors to isolate where the problem was occurring and found that it only happened when the CPU collector was enabled. We put some printfs around the calls inside the collect function and found that it was blocking on the call to wmi.Query.\r\n\r\nInterestingly, we did not see any pauses or breaks in the data while monitoring that data in perfmon while the query was running.\r\n\r\nWe dialled testing back to a 2 CPU VM running Windows 10 not doing anything particularly difficult or interesting and polling using \"curl $blah ; sleep 60\" in a loop.\r\n\r\nThe results suggest that something is going wrong every 17-18 minutes (the lines with *** were added by me):\r\n\r\n```\r\ntime=\"2017-07-03T10:31:38-07:00\" level=debug msg=\"OK: cpu collector succeeded after 0.032996s.\" source=\"exporter.go:90\"\r\n2017/07/03 10:32:38 *** Starting CPU Collector run...\r\n2017/07/03 10:32:38 *** Created WMI Query for CPU...\r\n2017/07/03 10:32:40 *** Ran WMI Query for CPU...\r\n2017/07/03 10:32:40 *** Sending data for 0 to exporter...\r\n2017/07/03 10:32:40 *** Sending data for 1 to exporter...\r\ntime=\"2017-07-03T10:32:40-07:00\" level=debug msg=\"OK: cpu collector succeeded after 2.324834s.\" source=\"exporter.go:90\"\r\n2017/07/03 10:33:40 *** Starting CPU Collector run...\r\n2017/07/03 10:33:40 *** Created WMI Query for CPU...\r\n2017/07/03 10:33:40 *** Ran WMI Query for CPU...\r\n2017/07/03 10:33:40 *** Sending data for 0 to exporter...\r\n2017/07/03 10:33:40 *** Sending data for 1 to exporter...\r\ntime=\"2017-07-03T10:33:40-07:00\" level=debug msg=\"OK: cpu collector succeeded after 0.046001s.\" source=\"exporter.go:90\"\r\n2017/07/03 10:34:40 *** Starting CPU Collector run...\r\n2017/07/03 10:34:40 *** Created WMI Query for CPU...\r\n2017/07/03 10:34:40 *** Ran WMI Query for CPU...\r\n2017/07/03 10:34:40 *** Sending data for 0 to exporter...\r\n2017/07/03 10:34:40 *** Sending data for 1 to exporter...\r\n```\r\n\r\n< snip a few more ~0.04 second runs >\r\n\r\n```\r\ntime=\"2017-07-03T10:46:41-07:00\" level=debug msg=\"OK: cpu collector succeeded after 0.044845s.\" source=\"exporter.go:90\"\r\n2017/07/03 10:47:41 *** Starting CPU Collector run...\r\n2017/07/03 10:47:41 *** Created WMI Query for CPU...\r\n2017/07/03 10:47:41 *** Ran WMI Query for CPU...\r\n2017/07/03 10:47:41 *** Sending data for 0 to exporter...\r\n2017/07/03 10:47:41 *** Sending data for 1 to exporter...\r\ntime=\"2017-07-03T10:47:41-07:00\" level=debug msg=\"OK: cpu collector succeeded after 0.038003s.\" source=\"exporter.go:90\"\r\n2017/07/03 10:48:41 *** Starting CPU Collector run...\r\n2017/07/03 10:50:05 *** Created WMI Query for CPU...\r\n2017/07/03 10:50:08 *** Ran WMI Query for CPU...\r\n2017/07/03 10:50:08 *** Sending data for 0 to exporter...\r\n2017/07/03 10:50:08 *** Sending data for 1 to exporter...\r\ntime=\"2017-07-03T10:50:08-07:00\" level=debug msg=\"OK: cpu collector succeeded after 86.787446s.\" source=\"exporter.go:90\"\r\n07/03 10:51:08 *** Starting CPU Collector run...\r\n2017/07/03 10:51:08 *** Created WMI Query for CPU...\r\n2017/07/03 10:51:08 *** Ran WMI Query for CPU...\r\n2017/07/03 10:51:08 *** Sending data for 0 to exporter...\r\n2017/07/03 10:51:08 *** Sending data for 1 to exporter...\r\ntime=\"2017-07-03T10:51:08-07:00\" level=debug msg=\"OK: cpu collector succeeded after 0.034084s.\" source=\"exporter.go:90\"\r\n```\r\n\r\nI tested again using official version v0.2.5 and again observed an unexpected increase in gathering time ~17 minutes after the last spike.\r\n\r\n```\r\ntime=\"2017-07-03T11:01:03-07:00\" level=info msg=\"Starting server on :9182\" source=\"exporter.go:206\"\r\ntime=\"2017-07-03T11:01:04-07:00\" level=debug msg=\"OK: cpu collector succeeded after 0.186394s.\" source=\"exporter.go:90\"\r\ntime=\"2017-07-03T11:02:04-07:00\" level=debug msg=\"OK: cpu collector succeeded after 0.022045s.\" source=\"exporter.go:90\"\r\ntime=\"2017-07-03T11:03:04-07:00\" level=debug msg=\"OK: cpu collector succeeded after 0.025063s.\" source=\"exporter.go:90\"\r\ntime=\"2017-07-03T11:04:05-07:00\" level=debug msg=\"OK: cpu collector succeeded after 0.031924s.\" source=\"exporter.go:90\"\r\ntime=\"2017-07-03T11:05:05-07:00\" level=debug msg=\"OK: cpu collector succeeded after 0.027066s.\" source=\"exporter.go:90\"\r\ntime=\"2017-07-03T11:06:07-07:00\" level=debug msg=\"OK: cpu collector succeeded after 0.036162s.\" source=\"exporter.go:90\"\r\ntime=\"2017-07-03T11:07:10-07:00\" level=debug msg=\"OK: cpu collector succeeded after 3.061992s.\" source=\"exporter.go:90\"\r\ntime=\"2017-07-03T11:08:10-07:00\" level=debug msg=\"OK: cpu collector succeeded after 0.036285s.\" source=\"exporter.go:90\"\r\ntime=\"2017-07-03T11:09:10-07:00\" level=debug msg=\"OK: cpu collector succeeded after 0.036368s.\" source=\"exporter.go:90\"\r\ntime=\"2017-07-03T11:10:11-07:00\" level=debug msg=\"OK: cpu collector succeeded after 0.187498s.\" source=\"exporter.go:90\"\r\ntime=\"2017-07-03T11:11:07-07:00\" level=debug msg=\"OK: cpu collector succeeded after 0.031065s.\" source=\"exporter.go:90\"\r\ntime=\"2017-07-03T11:12:07-07:00\" level=debug msg=\"OK: cpu collector succeeded after 0.030048s.\" source=\"exporter.go:90\"\r\ntime=\"2017-07-03T11:13:07-07:00\" level=debug msg=\"OK: cpu collector succeeded after 0.030922s.\" source=\"exporter.go:90\"\r\ntime=\"2017-07-03T11:14:08-07:00\" level=debug msg=\"OK: cpu collector succeeded after 0.030062s.\" source=\"exporter.go:90\"\r\ntime=\"2017-07-03T11:15:08-07:00\" level=debug msg=\"OK: cpu collector succeeded after 0.024992s.\" source=\"exporter.go:90\"\r\ntime=\"2017-07-03T11:16:08-07:00\" level=debug msg=\"OK: cpu collector succeeded after 0.030092s.\" source=\"exporter.go:90\"\r\ntime=\"2017-07-03T11:17:08-07:00\" level=debug msg=\"OK: cpu collector succeeded after 0.030072s.\" source=\"exporter.go:90\"\r\ntime=\"2017-07-03T11:18:08-07:00\" level=debug msg=\"OK: cpu collector succeeded after 0.029085s.\" source=\"exporter.go:90\"\r\ntime=\"2017-07-03T11:19:08-07:00\" level=debug msg=\"OK: cpu collector succeeded after 0.031077s.\" source=\"exporter.go:90\"\r\ntime=\"2017-07-03T11:20:08-07:00\" level=debug msg=\"OK: cpu collector succeeded after 0.031975s.\" source=\"exporter.go:90\"\r\ntime=\"2017-07-03T11:21:08-07:00\" level=debug msg=\"OK: cpu collector succeeded after 0.034084s.\" source=\"exporter.go:90\"\r\ntime=\"2017-07-03T11:22:08-07:00\" level=debug msg=\"OK: cpu collector succeeded after 0.031888s.\" source=\"exporter.go:90\"\r\ntime=\"2017-07-03T11:23:11-07:00\" level=debug msg=\"OK: cpu collector succeeded after 2.759751s.\" source=\"exporter.go:90\"\r\ntime=\"2017-07-03T11:24:11-07:00\" level=debug msg=\"OK: cpu collector succeeded after 0.036913s.\" source=\"exporter.go:90\"\r\n```\r\n\r\nI don't understand WMI enough to understand where to start digging, but it would be useful to understand if anyone else observes this.\r\n\r\nIf there's other data that is useful to gather. please let me know."},"comment":{"url":"https://api.github.com/repos/martinlindhe/wmi_exporter/issues/comments/366187670","html_url":"https://github.com/martinlindhe/wmi_exporter/issues/89#issuecomment-366187670","issue_url":"https://api.github.com/repos/martinlindhe/wmi_exporter/issues/89","id":366187670,"user":{"login":"leoluk","id":859697,"avatar_url":"https://avatars1.githubusercontent.com/u/859697?v=4","gravatar_id":"","url":"https://api.github.com/users/leoluk","html_url":"https://github.com/leoluk","followers_url":"https://api.github.com/users/leoluk/followers","following_url":"https://api.github.com/users/leoluk/following{/other_user}","gists_url":"https://api.github.com/users/leoluk/gists{/gist_id}","starred_url":"https://api.github.com/users/leoluk/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/leoluk/subscriptions","organizations_url":"https://api.github.com/users/leoluk/orgs","repos_url":"https://api.github.com/users/leoluk/repos","events_url":"https://api.github.com/users/leoluk/events{/privacy}","received_events_url":"https://api.github.com/users/leoluk/received_events","type":"User","site_admin":false},"created_at":"2018-02-16T09:41:31Z","updated_at":"2018-02-16T09:41:31Z","author_association":"NONE","body":"How is this different from https://github.com/martinlindhe/wmi_exporter/blob/94caf8ee61027bd02ae694353597741182b00829/exporter.go#L148 though?"}}
{"actor":{"display_login":"leoluk"}}