{"id":24003,"date":"2007-12-28T10:00:00","date_gmt":"2007-12-28T10:00:00","guid":{"rendered":"https:\/\/blogs.msdn.microsoft.com\/oldnewthing\/2007\/12\/28\/psychic-debugging-the-first-step-in-diagnosing-a-deadlock-is-a-simple-matter-of-following-the-money\/"},"modified":"2007-12-28T10:00:00","modified_gmt":"2007-12-28T10:00:00","slug":"psychic-debugging-the-first-step-in-diagnosing-a-deadlock-is-a-simple-matter-of-following-the-money","status":"publish","type":"post","link":"https:\/\/devblogs.microsoft.com\/oldnewthing\/20071228-00\/?p=24003","title":{"rendered":"Psychic debugging: The first step in diagnosing a deadlock is a simple matter of following the money"},"content":{"rendered":"

\nSomebody asked our team for help\nbecause they believed they hit a deadlock in their program’s UI.\n(It’s unclear why they asked our team,\nbut I guess since our team uses the window manager,\nand their program uses the window manager, we’re all in the same boat.\nYou’d think they’d ask the window manager team for help.)\n<\/p>\n

\nBut it turns out that solving the problem required no special\nexpertise.\nIn fact, you probably know enough to solve it, too.\n<\/p>\n

\n

\nHere are the interesting threads:\n<\/p>\n

\n  0  Id: 980.d30 Suspend: 1 Teb: 7ffdf000 Unfrozen\nChildEBP RetAddr\n0023dc90 7745dd8c ntdll!KiFastSystemCallRet\n0023dc94 774619e0 ntdll!ZwWaitForSingleObject+0xc\n0023dcf8 774618fb ntdll!RtlpWaitOnCriticalSection+0x154\n0023dd20 00cd03f2 ntdll!RtlEnterCriticalSection+0x152\n0023dd38 00cd0635 myapp!LogMsg+0x15\n0023dd58 00cd0c6a myapp!LogRawIndirect+0x27\n0023fcb8 00cb64a7 myapp!Log+0x62\n0023fce8 00cd7598 myapp!SimpleClientConfiguration::Cleanup+0x17\n0023fcf8 00cd8ffe myapp!MsgProc+0x1a9\n0023fd10 00cda1a9 myapp!Close+0x43\n0023fd24 761636d2 myapp!WndProc+0x62\n0023fd50 7616330c USER32!InternalCallWinProc+0x23\n0023fdc8 76164030 USER32!UserCallWinProcCheckWow+0x14b\n0023fe2c 76164088 USER32!DispatchMessageWorker+0x322\n0023fe3c 00cda3ba USER32!DispatchMessageW+0xf\n0023fe9c 00cd0273 myapp!GuiMain+0xe8\n0023feb4 00ccdeca myapp!wWinMain+0x87\n0023ff48 7735c6fc myapp!__wmainCRTStartup+0x150\n0023ff54 7742e33f kernel32!BaseThreadInitThunk+0xe\n0023ff94 00000000 ntdll!_RtlUserThreadStart+0x23\n   1  Id: 980.ce8 Suspend: 1 Teb: 7ffdd000 Unfrozen\nChildEBP RetAddr\n00f8d550 76162f81 ntdll!KiFastSystemCallRet\n00f8d554 76162fc4 USER32!NtUserSetWindowLong+0xc\n00f8d578 76162fe5 USER32!_SetWindowLong+0x131\n00f8d590 74aa5c2b USER32!SetWindowLongW+0x15\n00f8d5a4 74aa5b65 comctl32_74a70000!ClearWindowStyle+0x23\n00f8d5cc 74ca568f comctl32_74a70000!CCSetScrollInfo+0x103\n00f8d618 76164ea2 uxtheme!ThemeSetScrollInfoProc+0x10e\n00f8d660 00cdd913 USER32!SetScrollInfo+0x57\n00f8d694 00cdf0a4 myapp!SetScrollRange+0x3b\n00f8d6d4 00cdd777 myapp!TextOutputStringColor+0x134\n00f8d93c 00cd04c4 myapp!TextLogMsgProc+0x3db\n00f8d960 00cd0635 myapp!LogMsg+0xe7\n00f8d980 00cd0c6a myapp!LogRawIndirect+0x27\n00f8f8e0 00cd6367 myapp!Log+0x62\n00f8faf0 7735c6fc myapp!remote_ext::ServerListenerThread+0x45c\n00f8fafc 7742e33f kernel32!BaseThreadInitThunk+0xe\n00f8fb3c 00000000 ntdll!_RtlUserThreadStart+0x23\n<\/pre>\n<\/blockquote>\n
\nThe thing about debugging deadlocks is that you usually\ndon’t need to understand what’s going on.\nThe diagnosis is largely mechanical once you get your foot in the door.\n(Though sometimes it’s\n\nhard to get your initial footing<\/a>.)\n<\/p>\n
\nLet’s look at thread 0.\nIt is waiting for a critical section.\nThe owner of that critical section is thread 1.\nHow do I know that?\nWell, I could’ve debugged it, or I could’ve used my\npsychic powers to say,\n“Gosh, that function is called LogMsg<\/code>,\nand look there’s another thread that is inside the\nfunction LogMsg<\/code>.\nI bet that function is using a critical section to ensure\nthat only one thread uses it at a time.”\n<\/p>\n
\nOkay, so thread 0 is waiting for thread 1.\nWhat is thread 1 doing?\nWell, it entered the critical section back in the\nLogMsg<\/code> function,\nand then it did some text processing and, oh look,\nit’s doing a SetScrollInfo<\/code>.\nThe SetScrollInfo<\/code> went into comctl32<\/code>\nand ultimately resulted in a SetWindowLong<\/code>.\nThe window that the application passed to\nSetScrollInfo<\/code> is owned by thread 0.\nHow do I know that?\nWell, I could’ve debugged it, or I could’ve used my\npsychic powers to say,\n“Gosh, the change in the scroll info has led to a change\nin window styles, and the thread is trying to notify the\nwindow of the change in style.\nThe window clearly belongs to another thread; otherwise we wouldn’t\nbe stuck in the first place,\nand given that we see only two threads, there isn’t much choice\nas to what other thread it could be!”\n<\/p>\n
\nAt this point, I think you see the deadlock.\nThread 0 is waiting for thread 1 to exit the\ncritical section,\nbut thread 1 is waiting for thread 0 to process\nthe style change message.\n<\/p>\n
\nWhat happened here is that the program sent a message\nwhile holding a critical section.\nSince message handling can trigger hooks and cross-thread activity,\nyou cannot hold any resources when you send a message because\nthe hook or the message recipient might want to acquire that\nresource that you own,\nresulting in a deadlock.<\/p>\n","protected":false},"excerpt":{"rendered":"
Somebody asked our team for help because they believed they hit a deadlock in their program’s UI. (It’s unclear why they asked our team, but I guess since our team uses the window manager, and their program uses the window manager, we’re all in the same boat. You’d think they’d ask the window manager team […]<\/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":[26],"class_list":["post-24003","post","type-post","status-publish","format-standard","has-post-thumbnail","hentry","category-oldnewthing","tag-other"],"acf":[],"blog_post_summary":"
Somebody asked our team for help because they believed they hit a deadlock in their program’s UI. (It’s unclear why they asked our team, but I guess since our team uses the window manager, and their program uses the window manager, we’re all in the same boat. You’d think they’d ask the window manager team […]<\/p>\n","_links":{"self":[{"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/posts\/24003","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=24003"}],"version-history":[{"count":0,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/posts\/24003\/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=24003"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/categories?post=24003"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/tags?post=24003"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}