{"id":12663,"date":"2010-10-01T07:00:00","date_gmt":"2010-10-01T07:00:00","guid":{"rendered":"https:\/\/blogs.msdn.microsoft.com\/oldnewthing\/2010\/10\/01\/non-psychic-debugging-why-youre-leaking-timers\/"},"modified":"2010-10-01T07:00:00","modified_gmt":"2010-10-01T07:00:00","slug":"non-psychic-debugging-why-youre-leaking-timers","status":"publish","type":"post","link":"https:\/\/devblogs.microsoft.com\/oldnewthing\/20101001-00\/?p=12663","title":{"rendered":"Non-psychic debugging: Why you're leaking timers"},"content":{"rendered":"

\nI was not involved in this debugging puzzle,\nbut I was informed of its conclusions,\nand I think it illustrates both the process of debugging\nas well as uncovering a common type of defect.\nI’ve written it up in the style of a post-mortem.\n<\/p>\n

\n

\nA user reported that if they press and hold the F2 key\nfor about a minute,\nour program eventually stops working.\nAccording to Task Manager, our User object count has reached\n\nthe 10,000 object limit<\/a>,\nand closer inspection revealed that we had created over 9000 timer\nobjects.\n<\/p>\n

\nWe ran the debugger and\nset breakpoints on SetTimer<\/code> and KillTimer<\/code>\nto print to the debugger each timer ID as it was created and destroyed.\nVisual inspection of the output revealed that all but one of the IDs\nbeing created was matched with an appropriate destruction.\nWe re-ran the scenario with a conditional breakpoint on\nSetTimer<\/code> set to fire when that bad ID was set.\nIt didn’t take long for that breakpoint to fire,\nand we discovered that we were setting the timer against a\nNULL<\/code> window handle.\n<\/p>\n

\nA different developer on the team arrived at the same\nconclusion by a different route.\nInstead of watching timers being created and destroyed,\nthe developer dumped each timer message before it was dispatched\nand observed that most of the\nentries were associated with NULL<\/code> window handles.\n<\/p>\n

\nTwo independent analyses came to the same conclusion:\nWe were creating a bunch of thread timers and not destroying them.\n<\/p>\n

\nA closer inspection of the code revealed that\n\nthread timers were not intended in the first place<\/a>.\nEach time the user presses F2,\nthe code calls SetTimer<\/code> and passes a window handle\nit believes to be non-NULL<\/code>.\nThe timer is destroyed\nin the window procedure’s WM_TIMER<\/code> handler, but\nsince the timer was registered against the wrong window handle,\nthe WM_TIMER<\/code> is never received by the intended\ntarget’s window procedure,\nand the timer is never destroyed.\n<\/p>\n

\nThe window handle is NULL<\/code> due to a defect in the code\nwhich handles the F2 keypress:\nThe handle that the code wanted to use\nfor the timer had not yet been set.\n(It was set by a later step of F2 processing.)\nThe timer was being set by a helper function which is called both\nbefore and after the code that sets the handle, but it obviously was\nwritten on the assumption that it would only be called after.\n<\/p>\n

\nTo reduce the likelihood of this type of defect being introduced\nin the future,\nwe’re going to introduce a wrapper function around SetTimer<\/code>\nwhich asserts that the window handle is non-NULL<\/code> before\ncalling SetTimer<\/code>.\n(In the rare case that we actually want a thread timer,\nwe’ll have a second wrapper function called\nSetThreadTimer<\/code>.)\n<\/p>\n<\/blockquote>\n

\nI haven’t seen the wrapper function, but I suspect it goes\nsomething like this:\n<\/p>\n

\ninline UINT_PTR SetWindowTimer(\n    __in HWND hWnd, \/\/ NB - not optional\n    __in UINT_PTR nIDEvent,\n    __in UINT uElapse,\n    __in_opt TIMERPROC lpTimerFunc)\n{\n    assert(hWnd != NULL);\n    return SetTimer(hWnd, nIDEvent, uElapse, lpTimerFunc);\n}\ninline UINT_PTR SetThreadTimer(\n    __in UINT uElapse,\n    __in_opt TIMERPROC lpTimerFunc)\n{\n    return SetTimer(NULL, 0, uElapse, lpTimerFunc);\n}\n__declspec(deprecated)\nWINUSERAPI\nUINT_PTR\nWINAPI\nSetTimer(\n    __in_opt HWND hWnd,\n    __in UINT_PTR nIDEvent,\n    __in UINT uElapse,\n    __in_opt TIMERPROC lpTimerFunc);\n<\/pre>\n
\nThere are few interesting things here.\n<\/p>\n
\nFirst, observe that the annotation for the first parameter to\nSetWindowTimer<\/code> is __in<\/code> rather than\n__in_opt<\/code>. This indicates that the parameter\ncannot be NULL<\/code>.\nCode analysis tools can use this information to attempt to identify\npotential defects.\n<\/p>\n
\nSecond, observe that the SetThreadTimer<\/code> wrapper\nfunction omits the first two parameters.\nFor thread timers, the hWnd<\/code> passed to\nSetTimer<\/code> is always NULL<\/code> and the\nnIDEvent<\/code> is ignored.\n<\/p>\n
\nThird, after the two wrapper functions, we redeclare\nthe SetTimer<\/code>, but mark it as deprecated<\/code>\nso the compiler will complain if somebody tries to call the\noriginal function instead of one of the two wrappers.\n(The __declspec(deprecated)<\/code> extended attribute\nis a nonstandard Microsoft extension.)\n<\/p>\n
\nExercise<\/b>:\nWhy did I use __declspec(deprecated)<\/code> instead of\n#pragma deprecated(SetTimer)<\/code>?<\/p>\n","protected":false},"excerpt":{"rendered":"
I was not involved in this debugging puzzle, but I was informed of its conclusions, and I think it illustrates both the process of debugging as well as uncovering a common type of defect. I’ve written it up in the style of a post-mortem. A user reported that if they press and hold the F2 […]<\/p>\n","protected":false},"author":1069,"featured_media":111744,"comment_status":"open","ping_status":"closed","sticky":false,"template":"","format":"standard","meta":{"_acf_changed":false,"footnotes":""},"categories":[1],"tags":[25],"class_list":["post-12663","post","type-post","status-publish","format-standard","has-post-thumbnail","hentry","category-oldnewthing","tag-code"],"acf":[],"blog_post_summary":"
I was not involved in this debugging puzzle, but I was informed of its conclusions, and I think it illustrates both the process of debugging as well as uncovering a common type of defect. I’ve written it up in the style of a post-mortem. A user reported that if they press and hold the F2 […]<\/p>\n","_links":{"self":[{"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/posts\/12663","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/users\/1069"}],"replies":[{"embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/comments?post=12663"}],"version-history":[{"count":0,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/posts\/12663\/revisions"}],"wp:featuredmedia":[{"embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/media\/111744"}],"wp:attachment":[{"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/media?parent=12663"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/categories?post=12663"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/tags?post=12663"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}