Re: [PATCH] mm: warn about allocations which stall for too long

[Michal Hocko]

On Tue 27-09-16 21:57:26, Tetsuo Handa wrote:
> Michal Hocko wrote:
> > > > > ) rather than by line number, and surround __warn_memalloc_stall() 
> > > > > call with
> > > > > mutex in order to serialize warning messages because it is possible 
> > > > > that
> > > > > multiple allocation requests are stalling?
> > > > 
> > > > we do not use any lock in warn_alloc_failed so why this should be any
> > > > different?
> > > 
> > > warn_alloc_failed() is called for both __GFP_DIRECT_RECLAIM and
> > > !__GFP_DIRECT_RECLAIM allocation requests, and it is not allowed
> > > to sleep if !__GFP_DIRECT_RECLAIM. Thus, we have to tolerate that
> > > concurrent memory allocation failure messages make dmesg output
> > > unreadable. But __warn_memalloc_stall() is called for only
> > > __GFP_DIRECT_RECLAIM allocation requests. Thus, we are allowed to
> > > sleep in order to serialize concurrent memory allocation stall
> > > messages.
> > 
> > I still do not see a point. A single line about the warning and locked
> > dump_stack sounds sufficient to me.
> 
> printk() is slow operation. It is possible that two allocation requests
> start within time period needed for completing warn_alloc_failed().
> It is possible that multiple concurrent allocations are stalling when
> one of them cannot be satisfied. The consequence is multiple concurrent
> timeouts corrupting dmesg.
> http://I-love.SAKURA.ne.jp/tmp/serial-20160927-nolock.txt.xz
> (Please ignore Oops at do_task_stat(); it is irrelevant to this topic.)
> 
> If we guard it with mutex_lock(_lock)/mutex_unlock(_lock),
> no corruption.
> http://I-love.SAKURA.ne.jp/tmp/serial-20160927-lock.txt.xz

I have just posted v2 which reuses warn_alloc_failed infrastructure. If
we want to have a lock there then it should be a separate patch imho.
Ideally with and example from your above kernel log.
-- 
Michal Hocko
SUSE Labs

Re: [PATCH] mm: warn about allocations which stall for too long

[Michal Hocko]

On Tue 27-09-16 21:57:26, Tetsuo Handa wrote:
> Michal Hocko wrote:
> > > > > ) rather than by line number, and surround __warn_memalloc_stall() 
> > > > > call with
> > > > > mutex in order to serialize warning messages because it is possible 
> > > > > that
> > > > > multiple allocation requests are stalling?
> > > > 
> > > > we do not use any lock in warn_alloc_failed so why this should be any
> > > > different?
> > > 
> > > warn_alloc_failed() is called for both __GFP_DIRECT_RECLAIM and
> > > !__GFP_DIRECT_RECLAIM allocation requests, and it is not allowed
> > > to sleep if !__GFP_DIRECT_RECLAIM. Thus, we have to tolerate that
> > > concurrent memory allocation failure messages make dmesg output
> > > unreadable. But __warn_memalloc_stall() is called for only
> > > __GFP_DIRECT_RECLAIM allocation requests. Thus, we are allowed to
> > > sleep in order to serialize concurrent memory allocation stall
> > > messages.
> > 
> > I still do not see a point. A single line about the warning and locked
> > dump_stack sounds sufficient to me.
> 
> printk() is slow operation. It is possible that two allocation requests
> start within time period needed for completing warn_alloc_failed().
> It is possible that multiple concurrent allocations are stalling when
> one of them cannot be satisfied. The consequence is multiple concurrent
> timeouts corrupting dmesg.
> http://I-love.SAKURA.ne.jp/tmp/serial-20160927-nolock.txt.xz
> (Please ignore Oops at do_task_stat(); it is irrelevant to this topic.)
> 
> If we guard it with mutex_lock(_lock)/mutex_unlock(_lock),
> no corruption.
> http://I-love.SAKURA.ne.jp/tmp/serial-20160927-lock.txt.xz

I have just posted v2 which reuses warn_alloc_failed infrastructure. If
we want to have a lock there then it should be a separate patch imho.
Ideally with and example from your above kernel log.
-- 
Michal Hocko
SUSE Labs

Re: [PATCH] mm: warn about allocations which stall for too long

[Tetsuo Handa]

Michal Hocko wrote:
> > > > ) rather than by line number, and surround __warn_memalloc_stall() call 
> > > > with
> > > > mutex in order to serialize warning messages because it is possible that
> > > > multiple allocation requests are stalling?
> > > 
> > > we do not use any lock in warn_alloc_failed so why this should be any
> > > different?
> > 
> > warn_alloc_failed() is called for both __GFP_DIRECT_RECLAIM and
> > !__GFP_DIRECT_RECLAIM allocation requests, and it is not allowed
> > to sleep if !__GFP_DIRECT_RECLAIM. Thus, we have to tolerate that
> > concurrent memory allocation failure messages make dmesg output
> > unreadable. But __warn_memalloc_stall() is called for only
> > __GFP_DIRECT_RECLAIM allocation requests. Thus, we are allowed to
> > sleep in order to serialize concurrent memory allocation stall
> > messages.
> 
> I still do not see a point. A single line about the warning and locked
> dump_stack sounds sufficient to me.

printk() is slow operation. It is possible that two allocation requests
start within time period needed for completing warn_alloc_failed().
It is possible that multiple concurrent allocations are stalling when
one of them cannot be satisfied. The consequence is multiple concurrent
timeouts corrupting dmesg.
http://I-love.SAKURA.ne.jp/tmp/serial-20160927-nolock.txt.xz
(Please ignore Oops at do_task_stat(); it is irrelevant to this topic.)

If we guard it with mutex_lock(_lock)/mutex_unlock(_lock),
no corruption.
http://I-love.SAKURA.ne.jp/tmp/serial-20160927-lock.txt.xz

Deferring it when trylock() failed will be also possible.

Re: [PATCH] mm: warn about allocations which stall for too long

[Tetsuo Handa]

Michal Hocko wrote:
> > > > ) rather than by line number, and surround __warn_memalloc_stall() call 
> > > > with
> > > > mutex in order to serialize warning messages because it is possible that
> > > > multiple allocation requests are stalling?
> > > 
> > > we do not use any lock in warn_alloc_failed so why this should be any
> > > different?
> > 
> > warn_alloc_failed() is called for both __GFP_DIRECT_RECLAIM and
> > !__GFP_DIRECT_RECLAIM allocation requests, and it is not allowed
> > to sleep if !__GFP_DIRECT_RECLAIM. Thus, we have to tolerate that
> > concurrent memory allocation failure messages make dmesg output
> > unreadable. But __warn_memalloc_stall() is called for only
> > __GFP_DIRECT_RECLAIM allocation requests. Thus, we are allowed to
> > sleep in order to serialize concurrent memory allocation stall
> > messages.
> 
> I still do not see a point. A single line about the warning and locked
> dump_stack sounds sufficient to me.

printk() is slow operation. It is possible that two allocation requests
start within time period needed for completing warn_alloc_failed().
It is possible that multiple concurrent allocations are stalling when
one of them cannot be satisfied. The consequence is multiple concurrent
timeouts corrupting dmesg.
http://I-love.SAKURA.ne.jp/tmp/serial-20160927-nolock.txt.xz
(Please ignore Oops at do_task_stat(); it is irrelevant to this topic.)

If we guard it with mutex_lock(_lock)/mutex_unlock(_lock),
no corruption.
http://I-love.SAKURA.ne.jp/tmp/serial-20160927-lock.txt.xz

Deferring it when trylock() failed will be also possible.

Re: [PATCH] mm: warn about allocations which stall for too long

[Michal Hocko]

On Sat 24-09-16 12:00:07, Tetsuo Handa wrote:
> Michal Hocko wrote:
> > On Fri 23-09-16 23:36:22, Tetsuo Handa wrote:
> > > Michal Hocko wrote:
> > > > @@ -3659,6 +3661,15 @@ __alloc_pages_slowpath(gfp_t gfp_mask, unsigned 
> > > > int order,
> > > > else
> > > > no_progress_loops++;
> > > >  
> > > > +   /* Make sure we know about allocations which stall for too long 
> > > > */
> > > > +   if (!(gfp_mask & __GFP_NOWARN) && time_after(jiffies, 
> > > > alloc_start + stall_timeout)) {
> > > 
> > > Should we check !__GFP_NOWARN ? I think __GFP_NOWARN is likely used with
> > > __GFP_NORETRY, and __GFP_NORETRY is already checked by now.
> > > 
> > > I think printing warning regardless of __GFP_NOWARN is better because
> > > this check is similar to hungtask warning.
> > 
> > Well, if the user said to not warn we should really obey that. Why would
> > that matter?
> 
> __GFP_NOWARN is defined as "Do not print failure messages when memory
> allocation failed". It is not defined as "Do not print OOM killer messages
> when OOM killer is invoked". It is undefined that "Do not print stall
> messages when memory allocation is stalling".

Which is kind of expected as we warned only about allocation failures up
to now.

> If memory allocating threads were blocked on locks instead of doing direct
> reclaim, hungtask will be able to find stalling memory allocations without
> this change. Since direct reclaim prevents allocating threads from sleeping
> for long enough to be warned by hungtask, it is important that this change
> shall find allocating threads which cannot be warned by hungtask. That is,
> not printing warning messages for __GFP_NOWARN allocation requests looses
> the value of this change.

I dunno. If the user explicitly requests to not have allocation warning
then I think we should obey that. But this is not something I would be
really insisting hard. If others think that the check should be dropped
I can live with that.

[...]
> > > ) rather than by line number, and surround __warn_memalloc_stall() call 
> > > with
> > > mutex in order to serialize warning messages because it is possible that
> > > multiple allocation requests are stalling?
> > 
> > we do not use any lock in warn_alloc_failed so why this should be any
> > different?
> 
> warn_alloc_failed() is called for both __GFP_DIRECT_RECLAIM and
> !__GFP_DIRECT_RECLAIM allocation requests, and it is not allowed
> to sleep if !__GFP_DIRECT_RECLAIM. Thus, we have to tolerate that
> concurrent memory allocation failure messages make dmesg output
> unreadable. But __warn_memalloc_stall() is called for only
> __GFP_DIRECT_RECLAIM allocation requests. Thus, we are allowed to
> sleep in order to serialize concurrent memory allocation stall
> messages.

I still do not see a point. A single line about the warning and locked
dump_stack sounds sufficient to me.

-- 
Michal Hocko
SUSE Labs

Re: [PATCH] mm: warn about allocations which stall for too long

[Michal Hocko]

On Sat 24-09-16 12:00:07, Tetsuo Handa wrote:
> Michal Hocko wrote:
> > On Fri 23-09-16 23:36:22, Tetsuo Handa wrote:
> > > Michal Hocko wrote:
> > > > @@ -3659,6 +3661,15 @@ __alloc_pages_slowpath(gfp_t gfp_mask, unsigned 
> > > > int order,
> > > > else
> > > > no_progress_loops++;
> > > >  
> > > > +   /* Make sure we know about allocations which stall for too long 
> > > > */
> > > > +   if (!(gfp_mask & __GFP_NOWARN) && time_after(jiffies, 
> > > > alloc_start + stall_timeout)) {
> > > 
> > > Should we check !__GFP_NOWARN ? I think __GFP_NOWARN is likely used with
> > > __GFP_NORETRY, and __GFP_NORETRY is already checked by now.
> > > 
> > > I think printing warning regardless of __GFP_NOWARN is better because
> > > this check is similar to hungtask warning.
> > 
> > Well, if the user said to not warn we should really obey that. Why would
> > that matter?
> 
> __GFP_NOWARN is defined as "Do not print failure messages when memory
> allocation failed". It is not defined as "Do not print OOM killer messages
> when OOM killer is invoked". It is undefined that "Do not print stall
> messages when memory allocation is stalling".

Which is kind of expected as we warned only about allocation failures up
to now.

> If memory allocating threads were blocked on locks instead of doing direct
> reclaim, hungtask will be able to find stalling memory allocations without
> this change. Since direct reclaim prevents allocating threads from sleeping
> for long enough to be warned by hungtask, it is important that this change
> shall find allocating threads which cannot be warned by hungtask. That is,
> not printing warning messages for __GFP_NOWARN allocation requests looses
> the value of this change.

I dunno. If the user explicitly requests to not have allocation warning
then I think we should obey that. But this is not something I would be
really insisting hard. If others think that the check should be dropped
I can live with that.

[...]
> > > ) rather than by line number, and surround __warn_memalloc_stall() call 
> > > with
> > > mutex in order to serialize warning messages because it is possible that
> > > multiple allocation requests are stalling?
> > 
> > we do not use any lock in warn_alloc_failed so why this should be any
> > different?
> 
> warn_alloc_failed() is called for both __GFP_DIRECT_RECLAIM and
> !__GFP_DIRECT_RECLAIM allocation requests, and it is not allowed
> to sleep if !__GFP_DIRECT_RECLAIM. Thus, we have to tolerate that
> concurrent memory allocation failure messages make dmesg output
> unreadable. But __warn_memalloc_stall() is called for only
> __GFP_DIRECT_RECLAIM allocation requests. Thus, we are allowed to
> sleep in order to serialize concurrent memory allocation stall
> messages.

I still do not see a point. A single line about the warning and locked
dump_stack sounds sufficient to me.

-- 
Michal Hocko
SUSE Labs

Re: [PATCH] mm: warn about allocations which stall for too long

[Michal Hocko]

On Fri 23-09-16 10:34:01, Dave Hansen wrote:
> On 09/23/2016 01:15 AM, Michal Hocko wrote:
> > +   /* Make sure we know about allocations which stall for too long */
> > +   if (!(gfp_mask & __GFP_NOWARN) && time_after(jiffies, alloc_start + 
> > stall_timeout)) {
> > +   pr_warn("%s: page alloction stalls for %ums: order:%u 
> > mode:%#x(%pGg)\n",
> > +   current->comm, 
> > jiffies_to_msecs(jiffies-alloc_start),
> > +   order, gfp_mask, _mask);
> > +   stall_timeout += 10 * HZ;
> > +   dump_stack();
> > +   }
> 
> This would make an awesome tracepoint.  There's probably still plenty of
> value to having it in dmesg, but the configurability of tracepoints is
> hard to beat.

Currently we only have trace_mm_page_alloc in __alloc_pages_nodemask. I
think we want to add another one to mark the beginning of the allocation
so that we can track allocation latencies per allocation context and
ideally drop them down into sources - congestion waits, reclaim path,
slab reclaim etc. Janani Ravichandran is working on a script to do that
http://lkml.kernel.org/r/20160911222411.GA2854@janani-Inspiron-3521

But this sounds a bit orthogonal to my proposal here because I would
really like to warn unconditionally when an allocation stalls for
unreasonably long. Tracepoints are not an ideal tool for that because
you have to start collecting tracing output before this situations
happen. Moreover in my experience I often had to replace my local
debugging trace_printks by regular printks because the prior ones just
got lost under a heavy memory pressure.
-- 
Michal Hocko
SUSE Labs

Re: [PATCH] mm: warn about allocations which stall for too long

[Michal Hocko]

On Fri 23-09-16 10:34:01, Dave Hansen wrote:
> On 09/23/2016 01:15 AM, Michal Hocko wrote:
> > +   /* Make sure we know about allocations which stall for too long */
> > +   if (!(gfp_mask & __GFP_NOWARN) && time_after(jiffies, alloc_start + 
> > stall_timeout)) {
> > +   pr_warn("%s: page alloction stalls for %ums: order:%u 
> > mode:%#x(%pGg)\n",
> > +   current->comm, 
> > jiffies_to_msecs(jiffies-alloc_start),
> > +   order, gfp_mask, _mask);
> > +   stall_timeout += 10 * HZ;
> > +   dump_stack();
> > +   }
> 
> This would make an awesome tracepoint.  There's probably still plenty of
> value to having it in dmesg, but the configurability of tracepoints is
> hard to beat.

Currently we only have trace_mm_page_alloc in __alloc_pages_nodemask. I
think we want to add another one to mark the beginning of the allocation
so that we can track allocation latencies per allocation context and
ideally drop them down into sources - congestion waits, reclaim path,
slab reclaim etc. Janani Ravichandran is working on a script to do that
http://lkml.kernel.org/r/20160911222411.GA2854@janani-Inspiron-3521

But this sounds a bit orthogonal to my proposal here because I would
really like to warn unconditionally when an allocation stalls for
unreasonably long. Tracepoints are not an ideal tool for that because
you have to start collecting tracing output before this situations
happen. Moreover in my experience I often had to replace my local
debugging trace_printks by regular printks because the prior ones just
got lost under a heavy memory pressure.
-- 
Michal Hocko
SUSE Labs

Re: [PATCH] mm: warn about allocations which stall for too long

[Michal Hocko]

On Sat 24-09-16 23:19:04, Balbir Singh wrote:
> 
> 
> On 24/09/16 03:34, Dave Hansen wrote:
> > On 09/23/2016 01:15 AM, Michal Hocko wrote:
> >> +  /* Make sure we know about allocations which stall for too long */
> >> +  if (!(gfp_mask & __GFP_NOWARN) && time_after(jiffies, alloc_start + 
> >> stall_timeout)) {
> >> +  pr_warn("%s: page alloction stalls for %ums: order:%u 
> >> mode:%#x(%pGg)\n",
> >> +  current->comm, 
> >> jiffies_to_msecs(jiffies-alloc_start),
> >> +  order, gfp_mask, _mask);
> >> +  stall_timeout += 10 * HZ;
> >> +  dump_stack();
> >> +  }
> > 
> > This would make an awesome tracepoint.  There's probably still plenty of
> > value to having it in dmesg, but the configurability of tracepoints is
> > hard to beat.
> 
> An awesome tracepoint and a great place to trigger other tracepoints. With 
> stall timeout
> increasing every time, do we only care about the first instance when we 
> exceeded stall_timeout?
> Do we debug just that instance?

I am not sure I understand you here. The stall_timeout is increased to
see whether the situation is permanent of ephemeral. This is similar to
RCU lockup reports.
-- 
Michal Hocko
SUSE Labs

Re: [PATCH] mm: warn about allocations which stall for too long

[Michal Hocko]

On Sat 24-09-16 23:19:04, Balbir Singh wrote:
> 
> 
> On 24/09/16 03:34, Dave Hansen wrote:
> > On 09/23/2016 01:15 AM, Michal Hocko wrote:
> >> +  /* Make sure we know about allocations which stall for too long */
> >> +  if (!(gfp_mask & __GFP_NOWARN) && time_after(jiffies, alloc_start + 
> >> stall_timeout)) {
> >> +  pr_warn("%s: page alloction stalls for %ums: order:%u 
> >> mode:%#x(%pGg)\n",
> >> +  current->comm, 
> >> jiffies_to_msecs(jiffies-alloc_start),
> >> +  order, gfp_mask, _mask);
> >> +  stall_timeout += 10 * HZ;
> >> +  dump_stack();
> >> +  }
> > 
> > This would make an awesome tracepoint.  There's probably still plenty of
> > value to having it in dmesg, but the configurability of tracepoints is
> > hard to beat.
> 
> An awesome tracepoint and a great place to trigger other tracepoints. With 
> stall timeout
> increasing every time, do we only care about the first instance when we 
> exceeded stall_timeout?
> Do we debug just that instance?

I am not sure I understand you here. The stall_timeout is increased to
see whether the situation is permanent of ephemeral. This is similar to
RCU lockup reports.
-- 
Michal Hocko
SUSE Labs

Re: [PATCH] mm: warn about allocations which stall for too long

[Balbir Singh]

On 24/09/16 03:34, Dave Hansen wrote:
> On 09/23/2016 01:15 AM, Michal Hocko wrote:
>> +/* Make sure we know about allocations which stall for too long */
>> +if (!(gfp_mask & __GFP_NOWARN) && time_after(jiffies, alloc_start + 
>> stall_timeout)) {
>> +pr_warn("%s: page alloction stalls for %ums: order:%u 
>> mode:%#x(%pGg)\n",
>> +current->comm, 
>> jiffies_to_msecs(jiffies-alloc_start),
>> +order, gfp_mask, _mask);
>> +stall_timeout += 10 * HZ;
>> +dump_stack();
>> +}
> 
> This would make an awesome tracepoint.  There's probably still plenty of
> value to having it in dmesg, but the configurability of tracepoints is
> hard to beat.

An awesome tracepoint and a great place to trigger other tracepoints. With 
stall timeout
increasing every time, do we only care about the first instance when we 
exceeded stall_timeout?
Do we debug just that instance?

Balbir Singh.

Re: [PATCH] mm: warn about allocations which stall for too long

[Balbir Singh]

On 24/09/16 03:34, Dave Hansen wrote:
> On 09/23/2016 01:15 AM, Michal Hocko wrote:
>> +/* Make sure we know about allocations which stall for too long */
>> +if (!(gfp_mask & __GFP_NOWARN) && time_after(jiffies, alloc_start + 
>> stall_timeout)) {
>> +pr_warn("%s: page alloction stalls for %ums: order:%u 
>> mode:%#x(%pGg)\n",
>> +current->comm, 
>> jiffies_to_msecs(jiffies-alloc_start),
>> +order, gfp_mask, _mask);
>> +stall_timeout += 10 * HZ;
>> +dump_stack();
>> +}
> 
> This would make an awesome tracepoint.  There's probably still plenty of
> value to having it in dmesg, but the configurability of tracepoints is
> hard to beat.

An awesome tracepoint and a great place to trigger other tracepoints. With 
stall timeout
increasing every time, do we only care about the first instance when we 
exceeded stall_timeout?
Do we debug just that instance?

Balbir Singh.

Re: [PATCH] mm: warn about allocations which stall for too long

[Tetsuo Handa]

Michal Hocko wrote:
> On Fri 23-09-16 23:36:22, Tetsuo Handa wrote:
> > Michal Hocko wrote:
> > > @@ -3659,6 +3661,15 @@ __alloc_pages_slowpath(gfp_t gfp_mask, unsigned 
> > > int order,
> > >   else
> > >   no_progress_loops++;
> > >  
> > > + /* Make sure we know about allocations which stall for too long */
> > > + if (!(gfp_mask & __GFP_NOWARN) && time_after(jiffies, alloc_start + 
> > > stall_timeout)) {
> > 
> > Should we check !__GFP_NOWARN ? I think __GFP_NOWARN is likely used with
> > __GFP_NORETRY, and __GFP_NORETRY is already checked by now.
> > 
> > I think printing warning regardless of __GFP_NOWARN is better because
> > this check is similar to hungtask warning.
> 
> Well, if the user said to not warn we should really obey that. Why would
> that matter?

__GFP_NOWARN is defined as "Do not print failure messages when memory
allocation failed". It is not defined as "Do not print OOM killer messages
when OOM killer is invoked". It is undefined that "Do not print stall
messages when memory allocation is stalling".

If memory allocating threads were blocked on locks instead of doing direct
reclaim, hungtask will be able to find stalling memory allocations without
this change. Since direct reclaim prevents allocating threads from sleeping
for long enough to be warned by hungtask, it is important that this change
shall find allocating threads which cannot be warned by hungtask. That is,
not printing warning messages for __GFP_NOWARN allocation requests looses
the value of this change.

>  
> > > + pr_warn("%s: page alloction stalls for %ums: order:%u 
> > > mode:%#x(%pGg)\n",
> > > + current->comm, 
> > > jiffies_to_msecs(jiffies-alloc_start),
> > > + order, gfp_mask, _mask);
> > > + stall_timeout += 10 * HZ;
> > > + dump_stack();
> > 
> > Can we move this pr_warn() + dump_stack() to a separate function like
> > 
> > static void __warn_memalloc_stall(unsigned int order, gfp_t gfp_mask, 
> > unsigned long alloc_start)
> > {
> > pr_warn("%s: page alloction stalls for %ums: order:%u mode:%#x(%pGg)\n",
> > current->comm, jiffies_to_msecs(jiffies-alloc_start),
> > order, gfp_mask, _mask);
> > dump_stack();
> > }
> > 
> > in order to allow SystemTap scripts to perform additional actions by name 
> > (e.g.
> > 
> > # stap -g -e 'probe kernel.function("__warn_memalloc_stall").return { 
> > panic(); }
> 
> I find this reasoning and the use case really _absurd_, seriously! Pulling
> the warning into a separate function might be reasonable regardless,
> though. It matches warn_alloc_failed. Also if we find out we need some
> rate limitting or more checks it might just turn out being easier to
> follow rather than in the middle of an already complicated allocation
> slow path. I just do not like that the stall_timeout would have to stay
> in the original place or have it an in/out parameter.

SystemTap script shown above is just an example. What is nice is that
we can do whatever actions for examining what is going on by using a
function as if an interrupt handler. For example, when I was working at
support center, there was a support case where the customer's system always
reboots for unknown reason whenever specific action is taken. I inserted
SystemTap script shown above into a function which is called when a system
reboots, and I identified that the reason was SysRq-b which was triggered by
HA manager daemon due to misconfiguration. I used a reboot function as an
interrupt handler for examining why that handler was called. Likewise, we
can use __warn_memalloc_stall() as an interrupt handler for examining what
is going on. I think that there will be situations where existing printk()
does not provide enough information and thus examining a memory snapshot is
needed. Allowing tracing tools like SystemTap to insert a hook by function
name (instead of line number) is helpful anyway.

Going back to !(gfp_mask & __GFP_NOWARN) check, if you don't want to
print stall messages, you can move that check to inside
__warn_memalloc_stall(). Then, I can insert a SystemTap hook to print
stall messages for !(gfp_mask & __GFP_NOWARN) case. Even more, if you
are not sure what is best threshold, you can call a hook function every
second. The SystemTap script can check threshold and print warning if
necessary information are passed to that hook function. This resembles
LSM hooks. In the past, LSM hook was calling an empty function with
necessary information when LSM hook user (e.g. SELinux) is not registered.

> 
> > ) rather than by line number, and surround __warn_memalloc_stall() call with
> > mutex in order to serialize warning messages because it is possible that
> > multiple allocation requests are stalling?
> 
> we do not use any lock in warn_alloc_failed so why this should be any
> different?

warn_alloc_failed() is called for both __GFP_DIRECT_RECLAIM and
!__GFP_DIRECT_RECLAIM allocation requests, and it is 

Re: [PATCH] mm: warn about allocations which stall for too long

[Tetsuo Handa]

Michal Hocko wrote:
> On Fri 23-09-16 23:36:22, Tetsuo Handa wrote:
> > Michal Hocko wrote:
> > > @@ -3659,6 +3661,15 @@ __alloc_pages_slowpath(gfp_t gfp_mask, unsigned 
> > > int order,
> > >   else
> > >   no_progress_loops++;
> > >  
> > > + /* Make sure we know about allocations which stall for too long */
> > > + if (!(gfp_mask & __GFP_NOWARN) && time_after(jiffies, alloc_start + 
> > > stall_timeout)) {
> > 
> > Should we check !__GFP_NOWARN ? I think __GFP_NOWARN is likely used with
> > __GFP_NORETRY, and __GFP_NORETRY is already checked by now.
> > 
> > I think printing warning regardless of __GFP_NOWARN is better because
> > this check is similar to hungtask warning.
> 
> Well, if the user said to not warn we should really obey that. Why would
> that matter?

__GFP_NOWARN is defined as "Do not print failure messages when memory
allocation failed". It is not defined as "Do not print OOM killer messages
when OOM killer is invoked". It is undefined that "Do not print stall
messages when memory allocation is stalling".

If memory allocating threads were blocked on locks instead of doing direct
reclaim, hungtask will be able to find stalling memory allocations without
this change. Since direct reclaim prevents allocating threads from sleeping
for long enough to be warned by hungtask, it is important that this change
shall find allocating threads which cannot be warned by hungtask. That is,
not printing warning messages for __GFP_NOWARN allocation requests looses
the value of this change.

>  
> > > + pr_warn("%s: page alloction stalls for %ums: order:%u 
> > > mode:%#x(%pGg)\n",
> > > + current->comm, 
> > > jiffies_to_msecs(jiffies-alloc_start),
> > > + order, gfp_mask, _mask);
> > > + stall_timeout += 10 * HZ;
> > > + dump_stack();
> > 
> > Can we move this pr_warn() + dump_stack() to a separate function like
> > 
> > static void __warn_memalloc_stall(unsigned int order, gfp_t gfp_mask, 
> > unsigned long alloc_start)
> > {
> > pr_warn("%s: page alloction stalls for %ums: order:%u mode:%#x(%pGg)\n",
> > current->comm, jiffies_to_msecs(jiffies-alloc_start),
> > order, gfp_mask, _mask);
> > dump_stack();
> > }
> > 
> > in order to allow SystemTap scripts to perform additional actions by name 
> > (e.g.
> > 
> > # stap -g -e 'probe kernel.function("__warn_memalloc_stall").return { 
> > panic(); }
> 
> I find this reasoning and the use case really _absurd_, seriously! Pulling
> the warning into a separate function might be reasonable regardless,
> though. It matches warn_alloc_failed. Also if we find out we need some
> rate limitting or more checks it might just turn out being easier to
> follow rather than in the middle of an already complicated allocation
> slow path. I just do not like that the stall_timeout would have to stay
> in the original place or have it an in/out parameter.

SystemTap script shown above is just an example. What is nice is that
we can do whatever actions for examining what is going on by using a
function as if an interrupt handler. For example, when I was working at
support center, there was a support case where the customer's system always
reboots for unknown reason whenever specific action is taken. I inserted
SystemTap script shown above into a function which is called when a system
reboots, and I identified that the reason was SysRq-b which was triggered by
HA manager daemon due to misconfiguration. I used a reboot function as an
interrupt handler for examining why that handler was called. Likewise, we
can use __warn_memalloc_stall() as an interrupt handler for examining what
is going on. I think that there will be situations where existing printk()
does not provide enough information and thus examining a memory snapshot is
needed. Allowing tracing tools like SystemTap to insert a hook by function
name (instead of line number) is helpful anyway.

Going back to !(gfp_mask & __GFP_NOWARN) check, if you don't want to
print stall messages, you can move that check to inside
__warn_memalloc_stall(). Then, I can insert a SystemTap hook to print
stall messages for !(gfp_mask & __GFP_NOWARN) case. Even more, if you
are not sure what is best threshold, you can call a hook function every
second. The SystemTap script can check threshold and print warning if
necessary information are passed to that hook function. This resembles
LSM hooks. In the past, LSM hook was calling an empty function with
necessary information when LSM hook user (e.g. SELinux) is not registered.

> 
> > ) rather than by line number, and surround __warn_memalloc_stall() call with
> > mutex in order to serialize warning messages because it is possible that
> > multiple allocation requests are stalling?
> 
> we do not use any lock in warn_alloc_failed so why this should be any
> different?

warn_alloc_failed() is called for both __GFP_DIRECT_RECLAIM and
!__GFP_DIRECT_RECLAIM allocation requests, and it is 

Re: [PATCH] mm: warn about allocations which stall for too long

[Dave Hansen]

On 09/23/2016 01:15 AM, Michal Hocko wrote:
> + /* Make sure we know about allocations which stall for too long */
> + if (!(gfp_mask & __GFP_NOWARN) && time_after(jiffies, alloc_start + 
> stall_timeout)) {
> + pr_warn("%s: page alloction stalls for %ums: order:%u 
> mode:%#x(%pGg)\n",
> + current->comm, 
> jiffies_to_msecs(jiffies-alloc_start),
> + order, gfp_mask, _mask);
> + stall_timeout += 10 * HZ;
> + dump_stack();
> + }

This would make an awesome tracepoint.  There's probably still plenty of
value to having it in dmesg, but the configurability of tracepoints is
hard to beat.

Re: [PATCH] mm: warn about allocations which stall for too long

[Dave Hansen]

On 09/23/2016 01:15 AM, Michal Hocko wrote:
> + /* Make sure we know about allocations which stall for too long */
> + if (!(gfp_mask & __GFP_NOWARN) && time_after(jiffies, alloc_start + 
> stall_timeout)) {
> + pr_warn("%s: page alloction stalls for %ums: order:%u 
> mode:%#x(%pGg)\n",
> + current->comm, 
> jiffies_to_msecs(jiffies-alloc_start),
> + order, gfp_mask, _mask);
> + stall_timeout += 10 * HZ;
> + dump_stack();
> + }

This would make an awesome tracepoint.  There's probably still plenty of
value to having it in dmesg, but the configurability of tracepoints is
hard to beat.

Re: [PATCH] mm: warn about allocations which stall for too long

[Michal Hocko]

On Fri 23-09-16 23:36:22, Tetsuo Handa wrote:
> Michal Hocko wrote:
> > @@ -3659,6 +3661,15 @@ __alloc_pages_slowpath(gfp_t gfp_mask, unsigned int 
> > order,
> > else
> > no_progress_loops++;
> >  
> > +   /* Make sure we know about allocations which stall for too long */
> > +   if (!(gfp_mask & __GFP_NOWARN) && time_after(jiffies, alloc_start + 
> > stall_timeout)) {
> 
> Should we check !__GFP_NOWARN ? I think __GFP_NOWARN is likely used with
> __GFP_NORETRY, and __GFP_NORETRY is already checked by now.
> 
> I think printing warning regardless of __GFP_NOWARN is better because
> this check is similar to hungtask warning.

Well, if the user said to not warn we should really obey that. Why would
that matter?
 
> > +   pr_warn("%s: page alloction stalls for %ums: order:%u 
> > mode:%#x(%pGg)\n",
> > +   current->comm, 
> > jiffies_to_msecs(jiffies-alloc_start),
> > +   order, gfp_mask, _mask);
> > +   stall_timeout += 10 * HZ;
> > +   dump_stack();
> 
> Can we move this pr_warn() + dump_stack() to a separate function like
> 
> static void __warn_memalloc_stall(unsigned int order, gfp_t gfp_mask, 
> unsigned long alloc_start)
> {
>   pr_warn("%s: page alloction stalls for %ums: order:%u mode:%#x(%pGg)\n",
>   current->comm, jiffies_to_msecs(jiffies-alloc_start),
>   order, gfp_mask, _mask);
>   dump_stack();
> }
> 
> in order to allow SystemTap scripts to perform additional actions by name 
> (e.g.
> 
> # stap -g -e 'probe kernel.function("__warn_memalloc_stall").return { 
> panic(); }

I find this reasoning and the use case really _absurd_, seriously! Pulling
the warning into a separate function might be reasonable regardless,
though. It matches warn_alloc_failed. Also if we find out we need some
rate limitting or more checks it might just turn out being easier to
follow rather than in the middle of an already complicated allocation
slow path. I just do not like that the stall_timeout would have to stay
in the original place or have it an in/out parameter.

> ) rather than by line number, and surround __warn_memalloc_stall() call with
> mutex in order to serialize warning messages because it is possible that
> multiple allocation requests are stalling?

we do not use any lock in warn_alloc_failed so why this should be any
different?

-- 
Michal Hocko
SUSE Labs

Re: [PATCH] mm: warn about allocations which stall for too long

[Michal Hocko]

On Fri 23-09-16 23:36:22, Tetsuo Handa wrote:
> Michal Hocko wrote:
> > @@ -3659,6 +3661,15 @@ __alloc_pages_slowpath(gfp_t gfp_mask, unsigned int 
> > order,
> > else
> > no_progress_loops++;
> >  
> > +   /* Make sure we know about allocations which stall for too long */
> > +   if (!(gfp_mask & __GFP_NOWARN) && time_after(jiffies, alloc_start + 
> > stall_timeout)) {
> 
> Should we check !__GFP_NOWARN ? I think __GFP_NOWARN is likely used with
> __GFP_NORETRY, and __GFP_NORETRY is already checked by now.
> 
> I think printing warning regardless of __GFP_NOWARN is better because
> this check is similar to hungtask warning.

Well, if the user said to not warn we should really obey that. Why would
that matter?
 
> > +   pr_warn("%s: page alloction stalls for %ums: order:%u 
> > mode:%#x(%pGg)\n",
> > +   current->comm, 
> > jiffies_to_msecs(jiffies-alloc_start),
> > +   order, gfp_mask, _mask);
> > +   stall_timeout += 10 * HZ;
> > +   dump_stack();
> 
> Can we move this pr_warn() + dump_stack() to a separate function like
> 
> static void __warn_memalloc_stall(unsigned int order, gfp_t gfp_mask, 
> unsigned long alloc_start)
> {
>   pr_warn("%s: page alloction stalls for %ums: order:%u mode:%#x(%pGg)\n",
>   current->comm, jiffies_to_msecs(jiffies-alloc_start),
>   order, gfp_mask, _mask);
>   dump_stack();
> }
> 
> in order to allow SystemTap scripts to perform additional actions by name 
> (e.g.
> 
> # stap -g -e 'probe kernel.function("__warn_memalloc_stall").return { 
> panic(); }

I find this reasoning and the use case really _absurd_, seriously! Pulling
the warning into a separate function might be reasonable regardless,
though. It matches warn_alloc_failed. Also if we find out we need some
rate limitting or more checks it might just turn out being easier to
follow rather than in the middle of an already complicated allocation
slow path. I just do not like that the stall_timeout would have to stay
in the original place or have it an in/out parameter.

> ) rather than by line number, and surround __warn_memalloc_stall() call with
> mutex in order to serialize warning messages because it is possible that
> multiple allocation requests are stalling?

we do not use any lock in warn_alloc_failed so why this should be any
different?

-- 
Michal Hocko
SUSE Labs

Re: [PATCH] mm: warn about allocations which stall for too long

[Tetsuo Handa]

Michal Hocko wrote:
> @@ -3659,6 +3661,15 @@ __alloc_pages_slowpath(gfp_t gfp_mask, unsigned int 
> order,
>   else
>   no_progress_loops++;
>  
> + /* Make sure we know about allocations which stall for too long */
> + if (!(gfp_mask & __GFP_NOWARN) && time_after(jiffies, alloc_start + 
> stall_timeout)) {

Should we check !__GFP_NOWARN ? I think __GFP_NOWARN is likely used with
__GFP_NORETRY, and __GFP_NORETRY is already checked by now.

I think printing warning regardless of __GFP_NOWARN is better because
this check is similar to hungtask warning.

> + pr_warn("%s: page alloction stalls for %ums: order:%u 
> mode:%#x(%pGg)\n",
> + current->comm, 
> jiffies_to_msecs(jiffies-alloc_start),
> + order, gfp_mask, _mask);
> + stall_timeout += 10 * HZ;
> + dump_stack();

Can we move this pr_warn() + dump_stack() to a separate function like

static void __warn_memalloc_stall(unsigned int order, gfp_t gfp_mask, unsigned 
long alloc_start)
{
pr_warn("%s: page alloction stalls for %ums: order:%u mode:%#x(%pGg)\n",
current->comm, jiffies_to_msecs(jiffies-alloc_start),
order, gfp_mask, _mask);
dump_stack();
}

in order to allow SystemTap scripts to perform additional actions by name (e.g.

# stap -g -e 'probe kernel.function("__warn_memalloc_stall").return { panic(); }

) rather than by line number, and surround __warn_memalloc_stall() call with
mutex in order to serialize warning messages because it is possible that
multiple allocation requests are stalling?

> + }
> +
>   if (should_reclaim_retry(gfp_mask, order, ac, alloc_flags,
>did_some_progress > 0, no_progress_loops))
>   goto retry;
> -- 
> 2.9.3

Re: [PATCH] mm: warn about allocations which stall for too long

[Tetsuo Handa]

Michal Hocko wrote:
> @@ -3659,6 +3661,15 @@ __alloc_pages_slowpath(gfp_t gfp_mask, unsigned int 
> order,
>   else
>   no_progress_loops++;
>  
> + /* Make sure we know about allocations which stall for too long */
> + if (!(gfp_mask & __GFP_NOWARN) && time_after(jiffies, alloc_start + 
> stall_timeout)) {

Should we check !__GFP_NOWARN ? I think __GFP_NOWARN is likely used with
__GFP_NORETRY, and __GFP_NORETRY is already checked by now.

I think printing warning regardless of __GFP_NOWARN is better because
this check is similar to hungtask warning.

> + pr_warn("%s: page alloction stalls for %ums: order:%u 
> mode:%#x(%pGg)\n",
> + current->comm, 
> jiffies_to_msecs(jiffies-alloc_start),
> + order, gfp_mask, _mask);
> + stall_timeout += 10 * HZ;
> + dump_stack();

Can we move this pr_warn() + dump_stack() to a separate function like

static void __warn_memalloc_stall(unsigned int order, gfp_t gfp_mask, unsigned 
long alloc_start)
{
pr_warn("%s: page alloction stalls for %ums: order:%u mode:%#x(%pGg)\n",
current->comm, jiffies_to_msecs(jiffies-alloc_start),
order, gfp_mask, _mask);
dump_stack();
}

in order to allow SystemTap scripts to perform additional actions by name (e.g.

# stap -g -e 'probe kernel.function("__warn_memalloc_stall").return { panic(); }

) rather than by line number, and surround __warn_memalloc_stall() call with
mutex in order to serialize warning messages because it is possible that
multiple allocation requests are stalling?

> + }
> +
>   if (should_reclaim_retry(gfp_mask, order, ac, alloc_flags,
>did_some_progress > 0, no_progress_loops))
>   goto retry;
> -- 
> 2.9.3

Re: [PATCH] mm: warn about allocations which stall for too long

[Michal Hocko]

On Fri 23-09-16 16:44:26, Hillf Danton wrote:
> On Friday, September 23, 2016 4:32 PM, Michal Hocko wrote
> > On Fri 23-09-16 16:29:36, Hillf Danton wrote:
> > [...]
> > > > @@ -3659,6 +3661,15 @@ __alloc_pages_slowpath(gfp_t gfp_mask, unsigned 
> > > > int order,
> > > > else
> > > > no_progress_loops++;
> > > >
> > > > +   /* Make sure we know about allocations which stall for too long 
> > > > */
> > > > +   if (!(gfp_mask & __GFP_NOWARN) && time_after(jiffies, 
> > > > alloc_start + stall_timeout)) {
> > > > +   pr_warn("%s: page alloction stalls for %ums: order:%u 
> > > > mode:%#x(%pGg)\n",
> > > > +   current->comm, 
> > > > jiffies_to_msecs(jiffies-alloc_start),
> > >
> > > Better if pid is also printed.
> > 
> > I've tried to be consistent with warn_alloc_failed and that doesn't
> > print pid either. Maybe both of them should. Dunno
> > 
> With pid imho we can distinguish two tasks with same name in a simpler way. 

I've just checked dump_stack and dump_stack_print_info provides that
information already.
-- 
Michal Hocko
SUSE Labs

Re: [PATCH] mm: warn about allocations which stall for too long

[Michal Hocko]

On Fri 23-09-16 16:44:26, Hillf Danton wrote:
> On Friday, September 23, 2016 4:32 PM, Michal Hocko wrote
> > On Fri 23-09-16 16:29:36, Hillf Danton wrote:
> > [...]
> > > > @@ -3659,6 +3661,15 @@ __alloc_pages_slowpath(gfp_t gfp_mask, unsigned 
> > > > int order,
> > > > else
> > > > no_progress_loops++;
> > > >
> > > > +   /* Make sure we know about allocations which stall for too long 
> > > > */
> > > > +   if (!(gfp_mask & __GFP_NOWARN) && time_after(jiffies, 
> > > > alloc_start + stall_timeout)) {
> > > > +   pr_warn("%s: page alloction stalls for %ums: order:%u 
> > > > mode:%#x(%pGg)\n",
> > > > +   current->comm, 
> > > > jiffies_to_msecs(jiffies-alloc_start),
> > >
> > > Better if pid is also printed.
> > 
> > I've tried to be consistent with warn_alloc_failed and that doesn't
> > print pid either. Maybe both of them should. Dunno
> > 
> With pid imho we can distinguish two tasks with same name in a simpler way. 

I've just checked dump_stack and dump_stack_print_info provides that
information already.
-- 
Michal Hocko
SUSE Labs

Re: [PATCH] mm: warn about allocations which stall for too long

[Hillf Danton]

On Friday, September 23, 2016 4:32 PM, Michal Hocko wrote
> On Fri 23-09-16 16:29:36, Hillf Danton wrote:
> [...]
> > > @@ -3659,6 +3661,15 @@ __alloc_pages_slowpath(gfp_t gfp_mask, unsigned 
> > > int order,
> > >   else
> > >   no_progress_loops++;
> > >
> > > + /* Make sure we know about allocations which stall for too long */
> > > + if (!(gfp_mask & __GFP_NOWARN) && time_after(jiffies, alloc_start + 
> > > stall_timeout)) {
> > > + pr_warn("%s: page alloction stalls for %ums: order:%u 
> > > mode:%#x(%pGg)\n",
> > > + current->comm, 
> > > jiffies_to_msecs(jiffies-alloc_start),
> >
> > Better if pid is also printed.
> 
> I've tried to be consistent with warn_alloc_failed and that doesn't
> print pid either. Maybe both of them should. Dunno
> 
With pid imho we can distinguish two tasks with same name in a simpler way. 

> > > + order, gfp_mask, _mask);
> > > + stall_timeout += 10 * HZ;
> >
> > Alternativelyalloc_start = jiffies;
> 
> Then we would lose the cumulative time in the output which is imho
> helpful because you cannot tell whether the new warning is a new request
> or the old one still looping.
> 
Fair.

thanks
Hillf

Re: [PATCH] mm: warn about allocations which stall for too long

[Hillf Danton]

On Friday, September 23, 2016 4:32 PM, Michal Hocko wrote
> On Fri 23-09-16 16:29:36, Hillf Danton wrote:
> [...]
> > > @@ -3659,6 +3661,15 @@ __alloc_pages_slowpath(gfp_t gfp_mask, unsigned 
> > > int order,
> > >   else
> > >   no_progress_loops++;
> > >
> > > + /* Make sure we know about allocations which stall for too long */
> > > + if (!(gfp_mask & __GFP_NOWARN) && time_after(jiffies, alloc_start + 
> > > stall_timeout)) {
> > > + pr_warn("%s: page alloction stalls for %ums: order:%u 
> > > mode:%#x(%pGg)\n",
> > > + current->comm, 
> > > jiffies_to_msecs(jiffies-alloc_start),
> >
> > Better if pid is also printed.
> 
> I've tried to be consistent with warn_alloc_failed and that doesn't
> print pid either. Maybe both of them should. Dunno
> 
With pid imho we can distinguish two tasks with same name in a simpler way. 

> > > + order, gfp_mask, _mask);
> > > + stall_timeout += 10 * HZ;
> >
> > Alternativelyalloc_start = jiffies;
> 
> Then we would lose the cumulative time in the output which is imho
> helpful because you cannot tell whether the new warning is a new request
> or the old one still looping.
> 
Fair.

thanks
Hillf

Re: [PATCH] mm: warn about allocations which stall for too long

[Hillf Danton]

> 
> From: Michal Hocko 
> 
> Currently we do warn only about allocation failures but small
> allocations are basically nofail and they might loop in the page
> allocator for a long time.  Especially when the reclaim cannot make
> any progress - e.g. GFP_NOFS cannot invoke the oom killer and rely on
> a different context to make a forward progress in case there is a lot
> memory used by filesystems.
> 
> Give us at least a clue when something like this happens and warn about
> allocations which take more than 10s. Print the basic allocation context
> information along with the cumulative time spent in the allocation as
> well as the allocation stack. Repeat the warning after every 10 seconds so
> that we know that the problem is permanent rather than ephemeral.
> 
> Signed-off-by: Michal Hocko 
> ---
> 
> Hi,
> I am sending this as an RFC because I am not really sure what is the 
> reasonable
> timeout when to warn. I went with 10s because that should be close to "for 
> ever"
> from the user perspective. But maybe a shorter would be helpful as well?
> I didn't go with a tunable because I would rather not add a new one.
> 
> Thoughts? Ideas?
> 
>  mm/page_alloc.c | 11 +++
>  1 file changed, 11 insertions(+)
> 
> diff --git a/mm/page_alloc.c b/mm/page_alloc.c
> index 5155485057cb..d5faab8aa94d 100644
> --- a/mm/page_alloc.c
> +++ b/mm/page_alloc.c
> @@ -3485,6 +3485,8 @@ __alloc_pages_slowpath(gfp_t gfp_mask, unsigned int 
> order,
>   enum compact_result compact_result;
>   int compaction_retries = 0;
>   int no_progress_loops = 0;
> + unsigned long alloc_start = jiffies;
> + unsigned int stall_timeout = 10 * HZ;
> 
>   /*
>* In the slowpath, we sanity check order to avoid ever trying to
> @@ -3659,6 +3661,15 @@ __alloc_pages_slowpath(gfp_t gfp_mask, unsigned int 
> order,
>   else
>   no_progress_loops++;
> 
> + /* Make sure we know about allocations which stall for too long */
> + if (!(gfp_mask & __GFP_NOWARN) && time_after(jiffies, alloc_start + 
> stall_timeout)) {
> + pr_warn("%s: page alloction stalls for %ums: order:%u 
> mode:%#x(%pGg)\n",
> + current->comm, 
> jiffies_to_msecs(jiffies-alloc_start),

Better if pid is also printed.
> + order, gfp_mask, _mask);
> + stall_timeout += 10 * HZ;

Alternativelyalloc_start = jiffies;

> + dump_stack();
> + }
> +
>   if (should_reclaim_retry(gfp_mask, order, ac, alloc_flags,
>did_some_progress > 0, no_progress_loops))
>   goto retry;
> --
> 2.9.3
> 
thanks
Hillf

Re: [PATCH] mm: warn about allocations which stall for too long

[Hillf Danton]

> 
> From: Michal Hocko 
> 
> Currently we do warn only about allocation failures but small
> allocations are basically nofail and they might loop in the page
> allocator for a long time.  Especially when the reclaim cannot make
> any progress - e.g. GFP_NOFS cannot invoke the oom killer and rely on
> a different context to make a forward progress in case there is a lot
> memory used by filesystems.
> 
> Give us at least a clue when something like this happens and warn about
> allocations which take more than 10s. Print the basic allocation context
> information along with the cumulative time spent in the allocation as
> well as the allocation stack. Repeat the warning after every 10 seconds so
> that we know that the problem is permanent rather than ephemeral.
> 
> Signed-off-by: Michal Hocko 
> ---
> 
> Hi,
> I am sending this as an RFC because I am not really sure what is the 
> reasonable
> timeout when to warn. I went with 10s because that should be close to "for 
> ever"
> from the user perspective. But maybe a shorter would be helpful as well?
> I didn't go with a tunable because I would rather not add a new one.
> 
> Thoughts? Ideas?
> 
>  mm/page_alloc.c | 11 +++
>  1 file changed, 11 insertions(+)
> 
> diff --git a/mm/page_alloc.c b/mm/page_alloc.c
> index 5155485057cb..d5faab8aa94d 100644
> --- a/mm/page_alloc.c
> +++ b/mm/page_alloc.c
> @@ -3485,6 +3485,8 @@ __alloc_pages_slowpath(gfp_t gfp_mask, unsigned int 
> order,
>   enum compact_result compact_result;
>   int compaction_retries = 0;
>   int no_progress_loops = 0;
> + unsigned long alloc_start = jiffies;
> + unsigned int stall_timeout = 10 * HZ;
> 
>   /*
>* In the slowpath, we sanity check order to avoid ever trying to
> @@ -3659,6 +3661,15 @@ __alloc_pages_slowpath(gfp_t gfp_mask, unsigned int 
> order,
>   else
>   no_progress_loops++;
> 
> + /* Make sure we know about allocations which stall for too long */
> + if (!(gfp_mask & __GFP_NOWARN) && time_after(jiffies, alloc_start + 
> stall_timeout)) {
> + pr_warn("%s: page alloction stalls for %ums: order:%u 
> mode:%#x(%pGg)\n",
> + current->comm, 
> jiffies_to_msecs(jiffies-alloc_start),

Better if pid is also printed.
> + order, gfp_mask, _mask);
> + stall_timeout += 10 * HZ;

Alternativelyalloc_start = jiffies;

> + dump_stack();
> + }
> +
>   if (should_reclaim_retry(gfp_mask, order, ac, alloc_flags,
>did_some_progress > 0, no_progress_loops))
>   goto retry;
> --
> 2.9.3
> 
thanks
Hillf

Re: [PATCH] mm: warn about allocations which stall for too long

[Michal Hocko]

On Fri 23-09-16 16:29:36, Hillf Danton wrote:
[...]
> > @@ -3659,6 +3661,15 @@ __alloc_pages_slowpath(gfp_t gfp_mask, unsigned int 
> > order,
> > else
> > no_progress_loops++;
> > 
> > +   /* Make sure we know about allocations which stall for too long */
> > +   if (!(gfp_mask & __GFP_NOWARN) && time_after(jiffies, alloc_start + 
> > stall_timeout)) {
> > +   pr_warn("%s: page alloction stalls for %ums: order:%u 
> > mode:%#x(%pGg)\n",
> > +   current->comm, 
> > jiffies_to_msecs(jiffies-alloc_start),
> 
> Better if pid is also printed.

I've tried to be consistent with warn_alloc_failed and that doesn't
print pid either. Maybe both of them should. Dunno

> > +   order, gfp_mask, _mask);
> > +   stall_timeout += 10 * HZ;
> 
> Alternatively  alloc_start = jiffies;

Then we would lose the cumulative time in the output which is imho
helpful because you cannot tell whether the new warning is a new request
or the old one still looping.

> > +   dump_stack();
> > +   }
> > +
> > if (should_reclaim_retry(gfp_mask, order, ac, alloc_flags,
> >  did_some_progress > 0, no_progress_loops))
> > goto retry;
> > --
> > 2.9.3
> > 
> thanks
> Hillf
> 

-- 
Michal Hocko
SUSE Labs

Re: [PATCH] mm: warn about allocations which stall for too long

[Michal Hocko]

On Fri 23-09-16 16:29:36, Hillf Danton wrote:
[...]
> > @@ -3659,6 +3661,15 @@ __alloc_pages_slowpath(gfp_t gfp_mask, unsigned int 
> > order,
> > else
> > no_progress_loops++;
> > 
> > +   /* Make sure we know about allocations which stall for too long */
> > +   if (!(gfp_mask & __GFP_NOWARN) && time_after(jiffies, alloc_start + 
> > stall_timeout)) {
> > +   pr_warn("%s: page alloction stalls for %ums: order:%u 
> > mode:%#x(%pGg)\n",
> > +   current->comm, 
> > jiffies_to_msecs(jiffies-alloc_start),
> 
> Better if pid is also printed.

I've tried to be consistent with warn_alloc_failed and that doesn't
print pid either. Maybe both of them should. Dunno

> > +   order, gfp_mask, _mask);
> > +   stall_timeout += 10 * HZ;
> 
> Alternatively  alloc_start = jiffies;

Then we would lose the cumulative time in the output which is imho
helpful because you cannot tell whether the new warning is a new request
or the old one still looping.

> > +   dump_stack();
> > +   }
> > +
> > if (should_reclaim_retry(gfp_mask, order, ac, alloc_flags,
> >  did_some_progress > 0, no_progress_loops))
> > goto retry;
> > --
> > 2.9.3
> > 
> thanks
> Hillf
> 

-- 
Michal Hocko
SUSE Labs

[PATCH] mm: warn about allocations which stall for too long

[Michal Hocko]

From: Michal Hocko 

Currently we do warn only about allocation failures but small
allocations are basically nofail and they might loop in the page
allocator for a long time.  Especially when the reclaim cannot make
any progress - e.g. GFP_NOFS cannot invoke the oom killer and rely on
a different context to make a forward progress in case there is a lot
memory used by filesystems.

Give us at least a clue when something like this happens and warn about
allocations which take more than 10s. Print the basic allocation context
information along with the cumulative time spent in the allocation as
well as the allocation stack. Repeat the warning after every 10 seconds so
that we know that the problem is permanent rather than ephemeral.

Signed-off-by: Michal Hocko 
---

Hi,
I am sending this as an RFC because I am not really sure what is the reasonable
timeout when to warn. I went with 10s because that should be close to "for ever"
from the user perspective. But maybe a shorter would be helpful as well?
I didn't go with a tunable because I would rather not add a new one.

Thoughts? Ideas?

 mm/page_alloc.c | 11 +++
 1 file changed, 11 insertions(+)

diff --git a/mm/page_alloc.c b/mm/page_alloc.c
index 5155485057cb..d5faab8aa94d 100644
--- a/mm/page_alloc.c
+++ b/mm/page_alloc.c
@@ -3485,6 +3485,8 @@ __alloc_pages_slowpath(gfp_t gfp_mask, unsigned int order,
enum compact_result compact_result;
int compaction_retries = 0;
int no_progress_loops = 0;
+   unsigned long alloc_start = jiffies;
+   unsigned int stall_timeout = 10 * HZ;
 
/*
 * In the slowpath, we sanity check order to avoid ever trying to
@@ -3659,6 +3661,15 @@ __alloc_pages_slowpath(gfp_t gfp_mask, unsigned int 
order,
else
no_progress_loops++;
 
+   /* Make sure we know about allocations which stall for too long */
+   if (!(gfp_mask & __GFP_NOWARN) && time_after(jiffies, alloc_start + 
stall_timeout)) {
+   pr_warn("%s: page alloction stalls for %ums: order:%u 
mode:%#x(%pGg)\n",
+   current->comm, 
jiffies_to_msecs(jiffies-alloc_start),
+   order, gfp_mask, _mask);
+   stall_timeout += 10 * HZ;
+   dump_stack();
+   }
+
if (should_reclaim_retry(gfp_mask, order, ac, alloc_flags,
 did_some_progress > 0, no_progress_loops))
goto retry;
-- 
2.9.3

[PATCH] mm: warn about allocations which stall for too long

[Michal Hocko]

From: Michal Hocko 

Currently we do warn only about allocation failures but small
allocations are basically nofail and they might loop in the page
allocator for a long time.  Especially when the reclaim cannot make
any progress - e.g. GFP_NOFS cannot invoke the oom killer and rely on
a different context to make a forward progress in case there is a lot
memory used by filesystems.

Give us at least a clue when something like this happens and warn about
allocations which take more than 10s. Print the basic allocation context
information along with the cumulative time spent in the allocation as
well as the allocation stack. Repeat the warning after every 10 seconds so
that we know that the problem is permanent rather than ephemeral.

Signed-off-by: Michal Hocko 
---

Hi,
I am sending this as an RFC because I am not really sure what is the reasonable
timeout when to warn. I went with 10s because that should be close to "for ever"
from the user perspective. But maybe a shorter would be helpful as well?
I didn't go with a tunable because I would rather not add a new one.

Thoughts? Ideas?

 mm/page_alloc.c | 11 +++
 1 file changed, 11 insertions(+)

diff --git a/mm/page_alloc.c b/mm/page_alloc.c
index 5155485057cb..d5faab8aa94d 100644
--- a/mm/page_alloc.c
+++ b/mm/page_alloc.c
@@ -3485,6 +3485,8 @@ __alloc_pages_slowpath(gfp_t gfp_mask, unsigned int order,
enum compact_result compact_result;
int compaction_retries = 0;
int no_progress_loops = 0;
+   unsigned long alloc_start = jiffies;
+   unsigned int stall_timeout = 10 * HZ;
 
/*
 * In the slowpath, we sanity check order to avoid ever trying to
@@ -3659,6 +3661,15 @@ __alloc_pages_slowpath(gfp_t gfp_mask, unsigned int 
order,
else
no_progress_loops++;
 
+   /* Make sure we know about allocations which stall for too long */
+   if (!(gfp_mask & __GFP_NOWARN) && time_after(jiffies, alloc_start + 
stall_timeout)) {
+   pr_warn("%s: page alloction stalls for %ums: order:%u 
mode:%#x(%pGg)\n",
+   current->comm, 
jiffies_to_msecs(jiffies-alloc_start),
+   order, gfp_mask, _mask);
+   stall_timeout += 10 * HZ;
+   dump_stack();
+   }
+
if (should_reclaim_retry(gfp_mask, order, ac, alloc_flags,
 did_some_progress > 0, no_progress_loops))
goto retry;
-- 
2.9.3