On 4/24/19 7:35 AM, Vlastimil Babka wrote: > On 4/23/19 6:39 PM, Mike Kravetz wrote: >>> That being said, I do not think __GFP_RETRY_MAYFAIL is wrong here. It >>> looks like there is something wrong in the reclaim going on. >> >> Ok, I will start digging into that. Just wanted to make sure before I got >> into it too deep. >> >> BTW - This is very easy to reproduce. Just try to allocate more huge pages >> than will fit into memory. I see this 'reclaim taking forever' behavior on >> v5.1-rc5-mmotm-2019-04-19-14-53. Looks like it was there in v5.0 as well. > > I'd suspect this in should_continue_reclaim(): > > /* Consider stopping depending on scan and reclaim activity */ > if (sc->gfp_mask & __GFP_RETRY_MAYFAIL) { > /* > * For __GFP_RETRY_MAYFAIL allocations, stop reclaiming if the > * full LRU list has been scanned and we are still failing > * to reclaim pages. This full LRU scan is potentially > * expensive but a __GFP_RETRY_MAYFAIL caller really wants to > succeed > */ > if (!nr_reclaimed && !nr_scanned) > return false; > > And that for some reason, nr_scanned never becomes zero. But it's hard > to figure out through all the layers of functions :/
I got back to looking into the direct reclaim/compaction stalls when trying to allocate huge pages. As previously mentioned, the code is looping for a long time in shrink_node(). The routine should_continue_reclaim() returns true perhaps more often than it should. As Vlastmil guessed, my debug code output below shows nr_scanned is remaining non-zero for quite a while. This was on v5.2-rc6. To help determine what is happening, I added a counter to determine how many times should_continue_reclaim was returning true within one calling context from shrink_node. Every 1,000,000 calls, I set a 'debug flag' to get a little more information about what is happening before the next call. Here is output from debug code with some comments about what the debug code is showing. [ 1477.583859] ***should_continue_reclaim: setting debug_nr_scanned call 1000000 [ 1477.584698] shrink_inactive_list: nr_taken 1 = isolate_lru_pages(1, ... shrink_node calls shrink_node_memcg which calls shrink_list. shrink_list can increment sc->nr_scanned which is used to compute the value of nr_scanned passed to should_continue_reclaim. Here, we see that only one page is isolated for potential reclaim. [ 1477.585465] shrink_page_list: goto activate_locked 4 shrink_page_list determines that the page can not be reclaimed. The following code in shrink_page_list determines this. if (page_has_private(page)) { if (!try_to_release_page(page, sc->gfp_mask)) { /* Obviously, my debug code. */ if (sc->debug_nr_scanned) printk("shrink_page_list: goto activate_locked 4\n"); goto activate_locked; } [ 1477.586044] shrink_inactive_list: nr_reclaimed = 0 The bottom line is that page is not reclaimed. But, it was 'scanned' so .. [ 1477.586627] ***should_continue_reclaim: sc->nr_reclaimed 9 pages_for_compaction 1024 [ 1477.587546] nr_reclaimed 0, nr_scanned 1 should_continue_reclaim is called with nr_reclaimed 0, nr_scanned 1 [ 1477.588124] inactive_lru_pages 1 sc->nr_scanned 1000001 Since sc->nr_scanned is 1000001 for 1000001 calls, it looks like we scanned one page each time. Additional similar output without comments. [ 1511.200515] ***should_continue_reclaim: setting debug_nr_scanned call 2000000 [ 1511.201581] shrink_inactive_list: nr_taken 1 = isolate_lru_pages(1, ... [ 1511.202615] shrink_page_list: goto activate_locked 4 [ 1511.203561] shrink_inactive_list: nr_reclaimed = 0 [ 1511.204422] ***should_continue_reclaim: sc->nr_reclaimed 10 pages_for_compaction 1024 [ 1511.205785] nr_reclaimed 0, nr_scanned 1 [ 1511.206569] inactive_lru_pages 1 sc->nr_scanned 2000001 [ 1543.982310] ***should_continue_reclaim: setting debug_nr_scanned call 3000000 [ 1543.983692] shrink_inactive_list: nr_taken 1 = isolate_lru_pages(1, ... [ 1543.984645] shrink_page_list: goto activate_locked 4 [ 1543.985405] shrink_inactive_list: nr_reclaimed = 0 [ 1543.986386] ***should_continue_reclaim: sc->nr_reclaimed 11 pages_for_compaction 1024 [ 1543.987662] nr_reclaimed 0, nr_scanned 1 [ 1543.988423] inactive_lru_pages 1 sc->nr_scanned 3000001 [ 1577.104923] ***should_continue_reclaim: setting debug_nr_scanned call 4000000 [ 1577.105857] shrink_inactive_list: nr_taken 1 = isolate_lru_pages(1, ... [ 1577.106752] shrink_page_list: goto activate_locked 4 [ 1577.107454] shrink_inactive_list: nr_reclaimed = 0 [ 1577.108163] ***should_continue_reclaim: sc->nr_reclaimed 11 pages_for_compaction 1024 [ 1577.109423] nr_reclaimed 0, nr_scanned 1 [ 1577.110205] inactive_lru_pages 1 sc->nr_scanned 4000001 [ 1614.075236] ***should_continue_reclaim: setting debug_nr_scanned call 5000000 [ 1614.076375] shrink_inactive_list: nr_taken 1 = isolate_lru_pages(1, ... [ 1614.077410] shrink_page_list: goto activate_locked 4 [ 1614.078210] shrink_inactive_list: nr_reclaimed = 0 [ 1614.078913] ***should_continue_reclaim: sc->nr_reclaimed 13 pages_for_compaction 1024 [ 1614.079907] nr_reclaimed 0, nr_scanned 1 [ 1614.080496] inactive_lru_pages 1 sc->nr_scanned 5000001 [ 1650.360466] ***should_continue_reclaim: setting debug_nr_scanned call 6000000 [ 1650.361342] shrink_inactive_list: nr_taken 1 = isolate_lru_pages(1, ... [ 1650.362147] shrink_page_list: goto activate_locked 4 [ 1650.362759] shrink_inactive_list: nr_reclaimed = 0 [ 1650.363685] ***should_continue_reclaim: sc->nr_reclaimed 13 pages_for_compaction 1024 [ 1650.364648] nr_reclaimed 0, nr_scanned 1 [ 1650.365222] inactive_lru_pages 0 sc->nr_scanned 6000001 [ 1685.061380] ***should_continue_reclaim: setting debug_nr_scanned call 7000000 [ 1685.062529] shrink_inactive_list: nr_taken 1 = isolate_lru_pages(1, ... [ 1685.063615] shrink_page_list: goto activate_locked 4 [ 1685.064439] shrink_inactive_list: nr_reclaimed = 0 [ 1685.065244] ***should_continue_reclaim: sc->nr_reclaimed 14 pages_for_compaction 1024 [ 1685.066536] nr_reclaimed 0, nr_scanned 1 [ 1685.067356] inactive_lru_pages 1 sc->nr_scanned 7000001 [ 1719.103176] ***should_continue_reclaim: setting debug_nr_scanned call 8000000 [ 1719.104206] shrink_inactive_list: nr_taken 1 = isolate_lru_pages(1, ... [ 1719.105117] shrink_page_list: goto activate_locked 4 [ 1719.105781] shrink_inactive_list: nr_reclaimed = 0 [ 1719.106475] ***should_continue_reclaim: sc->nr_reclaimed 15 pages_for_compaction 1024 [ 1719.107499] nr_reclaimed 0, nr_scanned 1 [ 1719.108129] inactive_lru_pages 1 sc->nr_scanned 8000001 [ 1743.911025] ***should_continue_reclaim: false after 8711717 calls !nr_reclaimed && !nr_scanned Note that we do reclaim a 'few' pages along the way. After 8711717 calls should_continue_reclaim finally hits the condition where (!nr_reclaimed && !nr_scanned) and returns false. We were stuck looping in shrink node for about 5 minutes. Any additional insight, suggestions for additional debug, etc. would be appreciated. -- Mike Kravetz