{"id":1536,"date":"2012-04-20T14:58:10","date_gmt":"2012-04-20T19:58:10","guid":{"rendered":"http:\/\/www.kickflop.net\/blog\/?p=1536"},"modified":"2012-04-20T15:26:39","modified_gmt":"2012-04-20T20:26:39","slug":"parasitic-losses","status":"publish","type":"post","link":"https:\/\/www.kickflop.net\/blog\/2012\/04\/20\/parasitic-losses\/","title":{"rendered":"Parasitic Losses"},"content":{"rendered":"

Subtitle: “Derrrr … alert on stuff.”<\/p>\n

For awhile now, we’ve been in a foggy area with our monitoring and alerting. I’ve been aware for months that we should be doing more than we currently are. We’ve been running Nagios<\/a> for years and do an okay job with it in basic form. We also have Ganglia<\/a> metrics being collected for all of our servers, but they are largely ignored until needed for debugging. And finally, I’ve also just started seriously evaluating Graphite + various collectors as of 2 weeks ago. We do not currently<\/em> perform any alerting based on the data in Ganglia. It is all a slowly moving work in progress.<\/p>\n

Today, I just so happened to have a look at Ganglia and noticed 2 servers with elevated status (showing as yellow instead of green). They were both OpenAFS<\/a> “database” servers (we have 4), and for the sake of not sidetracking this blog post, are largely depended on for providing OpenAFS storage volume location information.<\/p>\n

It’s worth pointing out that there was no noticeable OpenAFS service degradation to the clients of the affected servers.<\/p>\n

We’ll only look at one because they both suffered the same problem. Below, you can see to the left side of the graphs the scene I was presented at the time I noticed the problem. We have completely flat load that is elevated, completely flat low CPU idle time, and a completely flat stream of ~360KB\/sec total network traffic:<\/p>\n

\"\"
\n\"\"
\n\"\"<\/p>\n

Though the graphs above show the last 4 hours, digging further back in time (not shown here) showed that this situation started at around 9AM on April 9th. The flat graph shape seen above at the left of all 3 graphs was found in our data from that day and time all the way to today! Hmmm. What changed around 9AM on April 9th? A little digging through my email and our revision control history showed absolutely nothing, so it was time to dive in with no hints.<\/p>\n

I found the OpenAFS Volume Location server process, vlserver<\/code>, eating a steady ~60% of the CPU on each of the 2 servers in question. Additionally, looking into the flat ~360KB\/sec network data with snoop<\/code> showed a solid stream of OpenAFS UDP packets coming from port 7001 on a client node to port 7003 (vlserver<\/code>!) on this server:<\/p>\n

\r\n# OpenAFS client request to vlserver then response back\r\nrogle.ourdomain -> shiva.ourdomain UDP D=7003 S=7001 LEN=56\r\nshiva.ourdomain -> rogle.ourdomain UDP D=7001 S=7003 LEN=40\r\n<\/pre>\n
Very rough calculations indicate at least 2500 of these exchanges were happening per second.<\/p>\n
Was this legit traffic from some long-running job created by one of the engineers? Looking more closely with snoop -x<\/code> showed that the request and response were identical every time. Something was clearly broken somewhere on host rogle<\/code>.<\/p>\n
Once logged into rogle<\/code>, I found 2 bash<\/code> processes with high CPU utilization time.  One is shown below.<\/p>\n
\r\njfivale  19137     1  0 Mar07 ?        03:43:03 bash\r\n<\/pre>\n
That’s not so interesting on its own, but adding in the detail that bash<\/code> for our users is actually \/afs\/rcf.ourdomain\/some\/path\/bin\/bash<\/code> changes things quite a bit.<\/p>\n
Brain says:<\/p>\n
Wait a second. Some number of days ago we had a weird situation where we had to kill off 5-10 bash<\/code> processes on several hosts due to them eating loads of CPU time. They had eaten far more CPU time than these, but this is getting familiar.<\/p><\/blockquote>\n
Sure enough, when I attached to the processes with strace -f<\/code>, they showed the same behavior as the broken processes a week or so ago:<\/p>\n
\r\n...\r\nrt_sigreturn(0x7)                       = 0\r\n--- SIGBUS (Bus error) @ 0 (0) ---\r\nrt_sigreturn(0x7)                       = 0\r\n--- SIGBUS (Bus error) @ 0 (0) ---\r\nrt_sigreturn(0x7)                       = 0\r\n--- SIGBUS (Bus error) @ 0 (0) ---\r\nrt_sigreturn(0x7)                       = 0\r\n--- SIGBUS (Bus error) @ 0 (0) ---\r\nrt_sigreturn(0x7)                       = 0\r\n--- SIGBUS (Bus error) @ 0 (0) ---\r\nrt_sigreturn(0x7)                       = 0\r\n--- SIGBUS (Bus error) @ 0 (0) --- \r\n...\r\n<\/pre>\n
or alternatively:<\/p>\n
\r\n...\r\n--- SIGSEGV (Segmentation fault) @ 0 (0) ---\r\nrt_sigreturn(0xb)                       = 316804680\r\n--- SIGSEGV (Segmentation fault) @ 0 (0) ---\r\nrt_sigreturn(0xb)                       = 316804680\r\n--- SIGSEGV (Segmentation fault) @ 0 (0) ---\r\nrt_sigreturn(0xb)                       = 316804680\r\n--- SIGSEGV (Segmentation fault) @ 0 (0) ---\r\nrt_sigreturn(0xb)                       = 316804680\r\n--- SIGSEGV (Segmentation fault) @ 0 (0) --- \r\n...\r\n<\/pre>\n
Once I had killed off the offending bash<\/code> processes, both of the affected servers returned to the normalcy you see in the right-hand portion of the graphs above.<\/p>\n
The question then was: What was going on with the bash<\/code> processes? Unfortunately, I have no answer. The bash<\/code> processes that spiraled out of control all belonged to a small subset of a certain department’s users and no other problematic instances of the same binary on the same hosts were reported.<\/p>\n
Alert on things that are abnormalities in your particular environment. Over 2500 volume location lookups per second is not normal for us. A flat and consistent load on our OpenAFS servers is also not normal. This should have been noticed and fixed within a few hours on April 9th.<\/p>\n","protected":false},"excerpt":{"rendered":"
Subtitle: “Derrrr … alert on stuff.”<\/p>\n","protected":false},"author":2,"featured_media":0,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":{"footnotes":""},"categories":[51,35,11,48],"tags":[],"class_list":["post-1536","post","type-post","status-publish","format-standard","hentry","category-devops","category-linux","category-sysadmin","category-unixlinux"],"_links":{"self":[{"href":"https:\/\/www.kickflop.net\/blog\/wp-json\/wp\/v2\/posts\/1536","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/www.kickflop.net\/blog\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/www.kickflop.net\/blog\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/www.kickflop.net\/blog\/wp-json\/wp\/v2\/users\/2"}],"replies":[{"embeddable":true,"href":"https:\/\/www.kickflop.net\/blog\/wp-json\/wp\/v2\/comments?post=1536"}],"version-history":[{"count":18,"href":"https:\/\/www.kickflop.net\/blog\/wp-json\/wp\/v2\/posts\/1536\/revisions"}],"predecessor-version":[{"id":1552,"href":"https:\/\/www.kickflop.net\/blog\/wp-json\/wp\/v2\/posts\/1536\/revisions\/1552"}],"wp:attachment":[{"href":"https:\/\/www.kickflop.net\/blog\/wp-json\/wp\/v2\/media?parent=1536"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/www.kickflop.net\/blog\/wp-json\/wp\/v2\/categories?post=1536"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/www.kickflop.net\/blog\/wp-json\/wp\/v2\/tags?post=1536"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}