Re: Performance regression in scsi sequential throughput (iozone)due to "e084b - page-allocator: preserve PFN ordering when __GFP_COLD isset"
From: Christian Ehrhardt
Date: Tue Feb 16 2010 - 11:47:41 EST
Mel Gorman wrote:
> On Mon, Feb 15, 2010 at 04:46:53PM +0100, Christian Ehrhardt wrote:
[...]
>> The differences in asm are pretty much the same, as before rmqueue_bulk was already inlined the actually intended change to its parameters was negligible.
>> I wondered if it would be important if that is a constant value (-1) or if the reason was caused by that shift. So I tried:
>>
>> 23 @@ -965,7 +965,7 @@
>> 24 set_page_private(page, migratetype);
>> 25 list = &page->lru;
>> 26 }
>> 27 - __mod_zone_page_state(zone, NR_FREE_PAGES, -(i << order));
>> 28 + __mod_zone_page_state(zone, NR_FREE_PAGES, -i);
>> 29 spin_unlock(&zone->lock);
>> 30 return i;
>> 31 }
>>
[...]
> It "fixes" it only by not calling direct reclaim when it should :(
yeah as we both realized -1 was not right so it was more a crazy workaround :-)
Anyway after that being a dead end again I dug even deeper into the details of direct_reclaim - I think we can agree that out of the counters we already know the race between try_to_free making progress and get_page not getting a page causing the congestion_wait is source of the issue.
So what I tried to bring some more light into all that was extending my perf counters to track a few more details in direct_reclaim.
Two patches are attached and apply after the other three already available in that thread.
The intention is
a) to track the time
a1) spent in try_to_free_pages
a2) consumed after try_to_free_pages until get_page_from_freelist
a3) spent in get_pages_from_freelist
b1) after seeing that order!=0 -> drain_all_pages I wondered if that might differ even all calls look like they have zero
b2) tracking the average amount of pages freed by try_to_free_pages for fast path and slow path (progres&!page)
Naming convention (otherwise it might get confusing here)
Good case - the scenario e.g. with e084b and 5f8dcc21 reverted resulting in high throughput and a low ratio of direct_reclaim running into progress&!page
Bad case - the scenario e.g. on a clean 2.6.32
Fast path - direct reclaim calls that did not run into progress&!page
Slow path - direct reclaim calls that ran into progress&!page ending up in a long congestion_wait and therefore called "slow" path
Mini summary of what we had before in huge tables:
fast path slow path
GOOD CASE ~98% ~1-3%
BAD CASE ~70% ~30%
-> leading to throughput impact of e.g. 600 mb/s with 16 iozone threads (worse with even more threads)
Out of the numbers I got the following things might help us to create a new approach to a solution.
The timings showed that that the so called slow case is actually much faster passing though direct_reclaim in bad case.
GOOD CASE duration
a1 Fast-avg-duration_pre_ttf_2_post_ttf 164099
a2 Fast-avg-duration_post_ttf_2_pre_get_page 459
a3 Fast-avg-duration_pre_get_page_2_post_get_page 346
a1 Slow-avg-duration_pre_ttf_2_post_ttf 127621
a2 Slow-avg-duration_post_ttf_2_pre_get_page 1957
a3 Slow-avg-duration_pre_get_page_2_post_get_page 256
BAD CASE duration deviation to good case in %
a1 Fast-avg-duration_pre_ttf_2_post_ttf 122921 -25.09%
a2 Fast-avg-duration_post_ttf_2_pre_get_page 521 13.53%
a3 Fast-avg-duration_pre_get_page_2_post_get_page 244 -29.55%
a1 Slow-avg-duration_pre_ttf_2_post_ttf 109740 -14.01%
a2 Slow-avg-duration_post_ttf_2_pre_get_page 250 -87.18%
a3 Slow-avg-duration_pre_get_page_2_post_get_page 117 -54.16%
That means that in the bad case the execution is much faster. Especially in the case that eventually runs into the slow path try_to_free is 14% faster, more important the time between try_to_free and get_pages is 87%! faster => less than a fifth and finally get_page is 54% faster, but that is probably just failing in an almost empty list which is fast^^.
As I checked order which always was zero the time is not spent in drain_all_pages and the only other thing left might be cond_resched ?!
Everything else are a few assignments so it can't be much else.
But why would e.g. not running into schedule in cond_resched cause get_pages to not find anything - I don't know and I would expect it should be the other way around - the faster you get from free to get the more pages should be left.
I thought the progress try_to_free_pages is doing might be important as well so I took numbers for that too.
>From those I see that the good case as well as the bad case has an average of 62 pages freed in fast path.
But in slow path they start to differ - while the good case that is running only seldom in that path anyway frees an average of 1.46 pages (that might be the thing causing it not getting a page eventually) in the bad case it makes a progress of avg 37 pages even in slow path.
PAGES-FREED fast path slow path
GOOD CASE ~62 ~1.46
BAD CASE ~62 ~37
Thinking of it as asking "how few pages do I have to free until I fall from fast to slow path" the kernels behave different it looks wrong but interesting.
The good case only drops to slow path (!page) in case of ~1.46 pages freed while the bad case seems to enter that much earlier with even 37 pages freed.
As order is always 0 and get_page afaik about getting just "one" page I wonder where these 37 pages disappeared especially as in bad case it is much faster getting to get_pages after freeing those ~37 pages.
Comments and ideas welcome!
--
Grüsse / regards, Christian Ehrhardt
IBM Linux Technology Center, Open Virtualization
Index: linux-2.6-git/kernel/sysctl.c
===================================================================
--- linux-2.6-git.orig/kernel/sysctl.c 2010-02-16 11:06:29.000000000 +0100
+++ linux-2.6-git/kernel/sysctl.c 2010-02-16 13:38:48.000000000 +0100
@@ -264,9 +264,64 @@
extern unsigned long perf_count_failed_pages_direct_reclaim_but_progress;
extern unsigned long perf_count_call_congestion_wait_from_alloc_pages_high_priority;
extern unsigned long perf_count_call_congestion_wait_from_alloc_pages_slowpath;
+
+extern unsigned long long perf_count_direct_reclaim_slow_dursum_pre_ttf_2_post_ttf;
+extern unsigned long long perf_count_direct_reclaim_slow_dursum_post_ttf_2_pre_get_page;
+extern unsigned long long perf_count_direct_reclaim_slow_dursum_pre_get_page_2_post_ttf;
+extern unsigned long long perf_count_direct_reclaim_fast_dursum_pre_ttf_2_post_ttf;
+extern unsigned long long perf_count_direct_reclaim_fast_dursum_post_ttf_2_pre_get_page;
+extern unsigned long long perf_count_direct_reclaim_fast_dursum_pre_get_page_2_post_ttf;
static struct ctl_table perf_table[] = {
{
.ctl_name = CTL_UNNUMBERED,
+ .procname = "perf_count_direct_reclaim_slow_dursum_pre_ttf_2_post_ttf",
+ .data = &perf_count_direct_reclaim_slow_dursum_pre_ttf_2_post_ttf,
+ .mode = 0666,
+ .maxlen = sizeof(unsigned long long),
+ .proc_handler = &proc_doulongvec_minmax,
+ },
+ {
+ .ctl_name = CTL_UNNUMBERED,
+ .procname = "perf_count_direct_reclaim_slow_dursum_post_ttf_2_pre_get_page",
+ .data = &perf_count_direct_reclaim_slow_dursum_post_ttf_2_pre_get_page,
+ .mode = 0666,
+ .maxlen = sizeof(unsigned long long),
+ .proc_handler = &proc_doulongvec_minmax,
+ },
+ {
+ .ctl_name = CTL_UNNUMBERED,
+ .procname = "perf_count_direct_reclaim_slow_dursum_pre_get_page_2_post_get_page",
+ .data = &perf_count_direct_reclaim_slow_dursum_pre_get_page_2_post_get_page,
+ .mode = 0666,
+ .maxlen = sizeof(unsigned long long),
+ .proc_handler = &proc_doulongvec_minmax,
+ },
+ {
+ .ctl_name = CTL_UNNUMBERED,
+ .procname = "perf_count_direct_reclaim_fast_dursum_pre_ttf_2_post_ttf",
+ .data = &perf_count_direct_reclaim_fast_dursum_pre_ttf_2_post_ttf,
+ .mode = 0666,
+ .maxlen = sizeof(unsigned long long),
+ .proc_handler = &proc_doulongvec_minmax,
+ },
+ {
+ .ctl_name = CTL_UNNUMBERED,
+ .procname = "perf_count_direct_reclaim_fast_dursum_post_ttf_2_pre_get_page",
+ .data = &perf_count_direct_reclaim_fast_dursum_post_ttf_2_pre_get_page,
+ .mode = 0666,
+ .maxlen = sizeof(unsigned long long),
+ .proc_handler = &proc_doulongvec_minmax,
+ },
+ {
+ .ctl_name = CTL_UNNUMBERED,
+ .procname = "perf_count_direct_reclaim_fast_dursum_pre_get_page_2_post_get_page",
+ .data = &perf_count_direct_reclaim_fast_dursum_pre_get_page_2_post_get_page,
+ .mode = 0666,
+ .maxlen = sizeof(unsigned long long),
+ .proc_handler = &proc_doulongvec_minmax,
+ },
+ {
+ .ctl_name = CTL_UNNUMBERED,
.procname = "perf_count_congestion_wait",
.data = &perf_count_congestion_wait,
.mode = 0666,
Index: linux-2.6-git/mm/page_alloc.c
===================================================================
--- linux-2.6-git.orig/mm/page_alloc.c 2010-02-16 11:06:29.000000000 +0100
+++ linux-2.6-git/mm/page_alloc.c 2010-02-16 13:38:24.000000000 +0100
@@ -51,6 +51,7 @@
#include <trace/events/kmem.h>
#include <asm/tlbflush.h>
+#include <asm/timex.h>
#include <asm/div64.h>
#include "internal.h"
@@ -1655,6 +1656,17 @@
unsigned long perf_count_failed_pages_direct_reclaim = 0;
unsigned long perf_count_failed_pages_direct_reclaim_but_progress = 0;
+unsigned long long perf_count_direct_reclaim_slow_dursum_pre_ttf_2_post_ttf = 0;
+unsigned long long perf_count_direct_reclaim_slow_dursum_post_ttf_2_pre_get_page = 0;
+unsigned long long perf_count_direct_reclaim_slow_dursum_pre_get_page_2_post_get_page = 0;
+unsigned long long perf_count_direct_reclaim_fast_dursum_pre_ttf_2_post_ttf = 0;
+unsigned long long perf_count_direct_reclaim_fast_dursum_post_ttf_2_pre_get_page = 0;
+unsigned long long perf_count_direct_reclaim_fast_dursum_pre_get_page_2_post_get_page = 0;
+
+static inline unsigned long long tod_duration_ns(unsigned long long from, unsigned long long to) {
+ return ((to*125)>>9)-((from*125)>>9);
+}
+
/* The really slow allocator path where we enter direct reclaim */
static inline struct page *
__alloc_pages_direct_reclaim(gfp_t gfp_mask, unsigned int order,
@@ -1665,6 +1677,7 @@
struct page *page = NULL;
struct reclaim_state reclaim_state;
struct task_struct *p = current;
+ unsigned long long t1,t2,t3,t4;
cond_resched();
@@ -1675,8 +1688,12 @@
reclaim_state.reclaimed_slab = 0;
p->reclaim_state = &reclaim_state;
+ t1 = get_clock();
+
*did_some_progress = try_to_free_pages(zonelist, order, gfp_mask, nodemask);
+ t2 = get_clock();
+
p->reclaim_state = NULL;
lockdep_clear_current_reclaim_state();
p->flags &= ~PF_MEMALLOC;
@@ -1686,17 +1703,28 @@
if (order != 0)
drain_all_pages();
+ t3 = get_clock();
if (likely(*did_some_progress))
page = get_page_from_freelist(gfp_mask, nodemask, order,
zonelist, high_zoneidx,
alloc_flags, preferred_zone,
migratetype);
+ t4 = get_clock();
perf_count_pages_direct_reclaim++;
if (!page)
perf_count_failed_pages_direct_reclaim++;
- if (!page && (*did_some_progress))
+ if (!page && (*did_some_progress)) {
perf_count_failed_pages_direct_reclaim_but_progress++;
+ perf_count_direct_reclaim_slow_dursum_pre_ttf_2_post_ttf += tod_duration_ns(t1,t2);
+ perf_count_direct_reclaim_slow_dursum_post_ttf_2_pre_get_page += tod_duration_ns(t2,t3);
+ perf_count_direct_reclaim_slow_dursum_pre_get_page_2_post_get_page += tod_duration_ns(t3,t4);
+ }
+ else {
+ perf_count_direct_reclaim_fast_dursum_pre_ttf_2_post_ttf += tod_duration_ns(t1,t2);
+ perf_count_direct_reclaim_fast_dursum_post_ttf_2_pre_get_page += tod_duration_ns(t2,t3);
+ perf_count_direct_reclaim_fast_dursum_pre_get_page_2_post_get_page += tod_duration_ns(t3,t4);
+ }
return page;
}
Index: linux-2.6-git/kernel/sysctl.c
===================================================================
--- linux-2.6-git.orig/kernel/sysctl.c 2010-02-16 13:38:48.000000000 +0100
+++ linux-2.6-git/kernel/sysctl.c 2010-02-16 15:07:21.000000000 +0100
@@ -267,13 +267,49 @@
extern unsigned long long perf_count_direct_reclaim_slow_dursum_pre_ttf_2_post_ttf;
extern unsigned long long perf_count_direct_reclaim_slow_dursum_post_ttf_2_pre_get_page;
-extern unsigned long long perf_count_direct_reclaim_slow_dursum_pre_get_page_2_post_ttf;
+extern unsigned long long perf_count_direct_reclaim_slow_dursum_pre_get_page_2_post_get_page;
extern unsigned long long perf_count_direct_reclaim_fast_dursum_pre_ttf_2_post_ttf;
extern unsigned long long perf_count_direct_reclaim_fast_dursum_post_ttf_2_pre_get_page;
-extern unsigned long long perf_count_direct_reclaim_fast_dursum_pre_get_page_2_post_ttf;
+extern unsigned long long perf_count_direct_reclaim_fast_dursum_pre_get_page_2_post_get_page;
+extern unsigned long perf_count_direct_reclaim_fast_sum_progress;
+extern unsigned long perf_count_direct_reclaim_slow_sum_progress;
+extern unsigned long perf_count_direct_reclaim_fast_sum_order;
+extern unsigned long perf_count_direct_reclaim_slow_sum_order;
static struct ctl_table perf_table[] = {
{
.ctl_name = CTL_UNNUMBERED,
+ .procname = "perf_count_direct_reclaim_slow_sum_progress",
+ .data = &perf_count_direct_reclaim_slow_sum_progress,
+ .mode = 0666,
+ .maxlen = sizeof(unsigned long long),
+ .proc_handler = &proc_doulongvec_minmax,
+ },
+ {
+ .ctl_name = CTL_UNNUMBERED,
+ .procname = "perf_count_direct_reclaim_slow_sum_order",
+ .data = &perf_count_direct_reclaim_slow_sum_order,
+ .mode = 0666,
+ .maxlen = sizeof(unsigned long long),
+ .proc_handler = &proc_doulongvec_minmax,
+ },
+ {
+ .ctl_name = CTL_UNNUMBERED,
+ .procname = "perf_count_direct_reclaim_fast_sum_progress",
+ .data = &perf_count_direct_reclaim_fast_sum_progress,
+ .mode = 0666,
+ .maxlen = sizeof(unsigned long long),
+ .proc_handler = &proc_doulongvec_minmax,
+ },
+ {
+ .ctl_name = CTL_UNNUMBERED,
+ .procname = "perf_count_direct_reclaim_fast_sum_order",
+ .data = &perf_count_direct_reclaim_fast_sum_order,
+ .mode = 0666,
+ .maxlen = sizeof(unsigned long long),
+ .proc_handler = &proc_doulongvec_minmax,
+ },
+ {
+ .ctl_name = CTL_UNNUMBERED,
.procname = "perf_count_direct_reclaim_slow_dursum_pre_ttf_2_post_ttf",
.data = &perf_count_direct_reclaim_slow_dursum_pre_ttf_2_post_ttf,
.mode = 0666,
Index: linux-2.6-git/mm/page_alloc.c
===================================================================
--- linux-2.6-git.orig/mm/page_alloc.c 2010-02-16 14:58:28.000000000 +0100
+++ linux-2.6-git/mm/page_alloc.c 2010-02-16 15:06:15.000000000 +0100
@@ -1663,6 +1663,11 @@
unsigned long long perf_count_direct_reclaim_fast_dursum_post_ttf_2_pre_get_page = 0;
unsigned long long perf_count_direct_reclaim_fast_dursum_pre_get_page_2_post_get_page = 0;
+unsigned long perf_count_direct_reclaim_fast_sum_progress = 0;
+unsigned long perf_count_direct_reclaim_slow_sum_progress = 0;
+unsigned long perf_count_direct_reclaim_fast_sum_order = 0;
+unsigned long perf_count_direct_reclaim_slow_sum_order = 0;
+
static inline unsigned long long tod_duration_ns(unsigned long long from, unsigned long long to) {
return ((to*125)>>9)-((from*125)>>9);
}
@@ -1719,11 +1724,17 @@
perf_count_direct_reclaim_slow_dursum_pre_ttf_2_post_ttf += tod_duration_ns(t1,t2);
perf_count_direct_reclaim_slow_dursum_post_ttf_2_pre_get_page += tod_duration_ns(t2,t3);
perf_count_direct_reclaim_slow_dursum_pre_get_page_2_post_get_page += tod_duration_ns(t3,t4);
+
+ perf_count_direct_reclaim_slow_sum_progress += *did_some_progress;
+ perf_count_direct_reclaim_slow_sum_order += order;
}
else {
perf_count_direct_reclaim_fast_dursum_pre_ttf_2_post_ttf += tod_duration_ns(t1,t2);
perf_count_direct_reclaim_fast_dursum_post_ttf_2_pre_get_page += tod_duration_ns(t2,t3);
perf_count_direct_reclaim_fast_dursum_pre_get_page_2_post_get_page += tod_duration_ns(t3,t4);
+
+ perf_count_direct_reclaim_fast_sum_progress += *did_some_progress;
+ perf_count_direct_reclaim_fast_sum_order += order;
}
return page;