Hi Dave,

On Wed, Jun 16, 2010 at 08:57:09AM +1000, Dave Airlie wrote:

...

(switching back to email, actually)

On Sun, 13 Jun 2010 13:01:57 GMT bugzilla-daemon@bugzilla.kernel.org wrote:

...

https://bugzilla.kernel.org/show_bug.cgi?id=16148

Mikko C. mikko.cal@gmail.com changed:

       What    |Removed                     |Added

---

             CC|                            |mikko.cal@gmail.com

--- Comment #8 from Mikko C. mikko.cal@gmail.com 2010-06-13 13:01:53 --- I have been getting this with 2.6.35-rc2 and rc3. Could it be the same problem?

X: page allocation failure. order:0, mode:0x4 Pid: 1514, comm: X Not tainted 2.6.35-rc3 #1 Call Trace: [<ffffffff8108ce49>] ? __alloc_pages_nodemask+0x629/0x680 [<ffffffff8108c920>] ? __alloc_pages_nodemask+0x100/0x680 [<ffffffffa00db8f3>] ? ttm_get_pages+0x2c3/0x448 [ttm] [<ffffffffa00d4658>] ? __ttm_tt_get_page+0x98/0xc0 [ttm] [<ffffffffa00d4988>] ? ttm_tt_populate+0x48/0x90 [ttm] [<ffffffffa00d4a26>] ? ttm_tt_bind+0x56/0xa0 [ttm] [<ffffffffa00d5230>] ? ttm_bo_handle_move_mem+0x1d0/0x430 [ttm] [<ffffffffa00d76d6>] ? ttm_bo_move_buffer+0x166/0x180 [ttm] [<ffffffffa00b9736>] ? drm_mm_kmalloc+0x26/0xc0 [drm] [<ffffffff81030ea9>] ? get_parent_ip+0x9/0x20 [<ffffffffa00d7786>] ? ttm_bo_validate+0x96/0x130 [ttm] [<ffffffffa00d7b35>] ? ttm_bo_init+0x315/0x390 [ttm] [<ffffffffa0122eb8>] ? radeon_bo_create+0x118/0x210 [radeon] [<ffffffffa0122fb0>] ? radeon_ttm_bo_destroy+0x0/0xb0 [radeon] [<ffffffffa013704c>] ? radeon_gem_object_create+0x8c/0x110 [radeon] [<ffffffffa013711f>] ? radeon_gem_create_ioctl+0x4f/0xe0 [radeon] [<ffffffffa00b10e6>] ? drm_ioctl+0x3d6/0x470 [drm] [<ffffffffa01370d0>] ? radeon_gem_create_ioctl+0x0/0xe0 [radeon] [<ffffffff810b965f>] ? do_sync_read+0xbf/0x100 [<ffffffff810c8965>] ? vfs_ioctl+0x35/0xd0 [<ffffffff810c8b28>] ? do_vfs_ioctl+0x88/0x530 [<ffffffff81031ed7>] ? sub_preempt_count+0x87/0xb0 [<ffffffff810c9019>] ? sys_ioctl+0x49/0x80 [<ffffffff810ba4fe>] ? sys_read+0x4e/0x90 [<ffffffff810024ab>] ? system_call_fastpath+0x16/0x1b

That's different. ttm_get_pages() looks pretty busted to me. It's not using __GFP_WAIT and it's not using __GFP_FS. It's using a plain GFP_DMA32 so it's using atomic allocations even though it doesn't need to. IOW, it's shooting itself in the head.

This is an accurate assessment.

...

Given that it will sometimes use GFP_HIGHUSER which includes __GFP_FS and __GFP_WAIT, I assume it can always include __GFP_FS and __GFP_WAIT. If so, it should very much do so. If not then the function is misdesigned and should be altered to take a gfp_t argument so the caller can tell ttm_get_pages() which is the strongest allocation mode which it may use.

...

[TTM] Unable to allocate page. radeon 0000:01:05.0: object_init failed for (7827456, 0x00000002) [drm:radeon_gem_object_create] *ERROR* Failed to allocate GEM object (7827456, 2, 4096, -12)

This bug actually broke stuff for you.

Something like this:

--- a/drivers/gpu/drm/ttm/ttm_page_alloc.c~a +++ a/drivers/gpu/drm/ttm/ttm_page_alloc.c @@ -677,7 +677,7 @@ int ttm_get_pages(struct list_head *page /* No pool for cached pages */ if (pool == NULL) { if (flags & TTM_PAGE_FLAG_DMA32)

• 	gfp_flags |= GFP_DMA32;
  

• 	gfp_flags |= GFP_KERNEL|GFP_DMA32;
  

  else gfp_flags |= GFP_HIGHUSER;

_

although I wonder whether it should be using pool->gfp_flags.

It's a shame that this code was developed and merged in secret :( Had we known, we could have looked at enhancing mempools to cover the requirement, or at implementing this in some generic fashion rather than hiding it down in drivers/gpu/drm.

Its been post to lkml at least once or twice over the past few years though not as much as it was posted to dri-devel, but that was because we had never seen anyone show any interest in it outside of kernel hackers. Originally I was going to use the generic allocator stuff ia64 uses for uncached allocations but it allocates memory ranges not pages so it wasn't useful. I also suggested getting a page flag for uncached allocator stuff, I was told to go write the code in my own corner and prove it was required. So I did, and it was cleaned up and worked on by others and I merged it. So can we lay off with the "in secret", the original code is nearly 2 years old at this point and just because -mm hackers choose to ignore it isn't our fault. Patches welcome.

No comment on this aspect of things.

So now back to the bug:

So the page pools are setup with gfp flags, in the normal case, 4 pools, one WC GFP_HIGHUSER pages, one UC HIGHUSER pages, one WC GFP_USER| GFP_DMA32, one UC GFP_USER|GFP_DMA32, so the pools are all fine, the problem here is the same as before we added the pools, which is the normal page allocation path, which needs the GFP_USER added instead of GFP_KERNEL.

That said I've noticed a lot more page allocation failure reports in 2.6.35-rcX than we've gotten for a long time, in code that hasn't changed (the AGP ones the other day for example) has something in the core MM regressed (again... didn't this happen back in 2.6.31 or something).

(cc'ing Mel who tracked these down before).

Ok, so there has been very little changed in the page allocator that might have caused this. The only possibility I can think of is [6dda9d: page allocator: reduce fragmentation in buddy allocator by adding buddies that are merging to the tail of the free lists] but I would have expected the patch to help, not hinder, this situation.

In the last few kernel releases when there has been a spike in high-order allocation, it has been largely due to an increased source of high-order callers from somewhere. I am 99% sure the last time I encountered this, I used the following script to debug it even though it's a bit of a hack. It uses ftrace to track high-order allocators and reports the number of high-order allocations (either atomic or normal) and the count of unique backtraces (to point the finger at bad callers)

Unfortunately, I don't have access to a suitable machine to test this with right now (my laptop isn't making high-order allocations to confirm yet) but I'm pretty sure it's the right one!

If you do some fixed set of tests with 2.6.34 and 2.6.35-rc2 with this script running and compare the reports, it might point the finger at a new source of frequent high-order allocations that might be leading to more failures. Do something like

./watch-highorder.pl -o highorder-2.6.34-report.txt PID=$! Do your tests # Two sigints in quick succession to make the monitor exit kill $PID kill $PID

==== CUT HERE ==== #!/usr/bin/perl # This is a tool that analyses the trace output related to page allocation, # sums up the number of high-order allocations taking place and who the # callers are # # Example usage: trace-pagealloc-highorder.pl -o output-report.txt # options # -o, --output Where to store the report # # Copyright (c) IBM Corporation 2009 # Author: Mel Gorman mel@csn.ul.ie use strict; use Getopt::Long;

# Tracepoint events use constant MM_PAGE_ALLOC => 1; use constant EVENT_UNKNOWN => 7;

use constant HIGH_NORMAL_HIGHORDER_ALLOC => 10; use constant HIGH_ATOMIC_HIGHORDER_ALLOC => 11;

my $opt_output; my %stats; my %unique_events; my $last_updated = 0;

$stats{HIGH_NORMAL_HIGHORDER_ALLOC} = 0; $stats{HIGH_ATOMIC_HIGHORDER_ALLOC} = 0;

# Catch sigint and exit on request my $sigint_report = 0; my $sigint_exit = 0; my $sigint_pending = 0; my $sigint_received = 0; sub sigint_handler { my $current_time = time; if ($current_time - 2 > $sigint_received) { print "SIGINT received, report pending. Hit ctrl-c again to exit\n"; $sigint_report = 1; } else { if (!$sigint_exit) { print "Second SIGINT received quickly, exiting\n"; } $sigint_exit++; }

if ($sigint_exit > 3) { print "Many SIGINTs received, exiting now without report\n"; exit; }

$sigint_received = $current_time; $sigint_pending = 1; } $SIG{INT} = "sigint_handler";

# Parse command line options GetOptions( 'output=s' => $opt_output, );

# Defaults for dynamically discovered regex's my $regex_pagealloc_default = 'page=([0-9a-f]*) pfn=([0-9]*) order=([-0-9]*) migratetype=([-0-9]*) gfp_flags=([A-Z_|]*)';

# Dyanically discovered regex my $regex_pagealloc;

# Static regex used. Specified like this for readability and for use with /o # (process_pid) (cpus ) ( time ) (tpoint ) (details) my $regex_traceevent = '\s*([a-zA-Z0-9-]*)\s*([[0-9]*])\s*([0-9.]*):\s*([a-zA-Z_]*):\s*(.*)'; my $regex_statname = '[-0-9]*\s((.*)).*'; my $regex_statppid = '[-0-9]*\s(.*)\s[A-Za-z]\s([0-9]*).*';

sub generate_traceevent_regex { my $event = shift; my $default = shift; my $regex;

# Read the event format or use the default if (!open (FORMAT, "/sys/kernel/debug/tracing/events/$event/format")) { $regex = $default; } else { my $line; while (!eof(FORMAT)) { $line = <FORMAT>; if ($line =~ /^print fmt:\s"(.*)",.*/) { $regex = $1; $regex =~ s/%p/([0-9a-f]*)/g; $regex =~ s/%d/([-0-9]*)/g; $regex =~ s/%lu/([0-9]*)/g; $regex =~ s/%s/([A-Z_|]*)/g; $regex =~ s/(REC->gfp_flags).*/REC->gfp_flags/; $regex =~ s/",.*//; } } }

# Verify fields are in the right order my $tuple; foreach $tuple (split /\s/, $regex) { my ($key, $value) = split(/=/, $tuple); my $expected = shift; if ($key ne $expected) { print("WARNING: Format not as expected '$key' != '$expected'"); $regex =~ s/$key=((.*))/$key=$1/; } }

if (defined shift) { die("Fewer fields than expected in format"); }

return $regex; } $regex_pagealloc = generate_traceevent_regex("kmem/mm_page_alloc", $regex_pagealloc_default, "page", "pfn", "order", "migratetype", "gfp_flags");

sub process_events { my $traceevent; my $process_pid = 0; my $cpus; my $timestamp; my $tracepoint; my $details; my $statline; my $nextline = 1;

# Read each line of the event log EVENT_PROCESS: while (($traceevent = <TRACING>) && !$sigint_exit) { SKIP_LINEREAD:

if ($traceevent eq "") { last EVENT_PROCSS; }

if ($traceevent =~ /$regex_traceevent/o) { $process_pid = $1; $tracepoint = $4; } else { next; }

# Perl Switch() sucks majorly if ($tracepoint eq "mm_page_alloc") { my ($page, $order, $gfp_flags, $type); my ($atomic); my $details = $5;

if ($details !~ /$regex_pagealloc/o) { print "WARNING: Failed to parse mm_page_alloc as expected\n"; print "$details\n"; print "$regex_pagealloc\n"; print "\n"; next; } $page = $1; $order = $3; $gfp_flags = $5;

# Only concerned with high-order allocs if ($order == 0) { next; }

$stats{MM_PAGE_ALLOC}++;

if ($gfp_flags =~ /ATOMIC/) { $stats{HIGH_ATOMIC_HIGHORDER_ALLOC}++; $type = "atomic"; } else { $stats{HIGH_NORMAL_HIGHORDER_ALLOC}++; $type = "normal"; }

# Record the stack trace $traceevent = <TRACING>; if ($traceevent !~ /stack trace/) { goto SKIP_LINEREAD; } my $event = "order=$order $type gfp_flags=$gfp_flags\n";; while ($traceevent = <TRACING>) { if ($traceevent !~ /^ =>/) { $unique_events{$event}++; my $current = time;

if ($current - $last_updated > 60) { $last_updated = $current; update_report(); } goto SKIP_LINEREAD; } $event .= $traceevent; } } else { $stats{EVENT_UNKNOWN}++; }

if ($sigint_pending) { last EVENT_PROCESS; } } }

sub update_report() { my $event; open (REPORT, ">$opt_output") || die ("Failed to open $opt_output for writing");

foreach $event (keys %unique_events) { print REPORT $unique_events{$event} . " instances $event\n"; } print REPORT "High-order normal allocations: " . $stats{HIGH_NORMAL_HIGHORDER_ALLOC} . "\n"; print REPORT "High-order atomic allocations: " . $stats{HIGH_ATOMIC_HIGHORDER_ALLOC} . "\n";

close REPORT; }

sub print_report() { print "\nReport\n"; open (REPORT, $opt_output) || die ("Failed to open $opt_output for reading"); while (<REPORT>) { print $_; } close REPORT; }

# Process events or signals until neither is available sub signal_loop() { my $sigint_processed; do { $sigint_processed = 0; process_events();

# Handle pending signals if any if ($sigint_pending) { my $current_time = time;

if ($sigint_exit) { print "Received exit signal\n"; $sigint_pending = 0; } if ($sigint_report) { if ($current_time >= $sigint_received + 2) { update_report(); print_report(); $sigint_report = 0; $sigint_pending = 0; $sigint_processed = 1; $sigint_exit = 0; } } } } while ($sigint_pending || $sigint_processed); }

sub set_traceoption($) { my $option = shift;

open(TRACEOPT, ">/sys/kernel/debug/tracing/trace_options") || die("Failed to open trace_options"); print TRACEOPT $option; close TRACEOPT; }

sub enable_tracing($) { my $tracing = shift;

open(TRACING, ">/sys/kernel/debug/tracing/events/$tracing/enable") || die("Failed to open tracing event $tracing"); print TRACING "1"; close TRACING; }

sub disable_tracing($) { my $tracing = shift;

open(TRACING, ">/sys/kernel/debug/tracing/events/$tracing/enable") || die("Failed to open tracing event $tracing"); print TRACING "0"; close TRACING;

}

set_traceoption("stacktrace"); set_traceoption("sym-offset"); set_traceoption("sym-addr"); enable_tracing("kmem/mm_page_alloc"); open(TRACING, "/sys/kernel/debug/tracing/trace_pipe") || die("Failed to open trace_pipe"); signal_loop(); close TRACING; disable_tracing("kmem/mm_page_alloc"); update_report(); print_report();