[RFC] [PATCH] Performance of del_single_shot_timer_sync

[RFC] [PATCH] Performance of del_single_shot_timer_sync

[shobhit dayal]

                                                                                                                                                                                  This is with reference to the del_timer_sync patch submitted by Geoff Gustafson http://lwn.net/Articles/84839/
I profiled a postgress load on a 8p( 4 nodes) NUMA machine. This
profiler logs functions that access memory on remote nodes, and
del_timer_sync was one of the top few functions doing this. The culprit
is the for loop in del_timer_sync that reads the running_timer field of
the per cpu tvec_bases_t structure on all nodes in the system. It get
invoked most times from del_singleshot_timer_sync. Andrew Morton had
suggested a patch for this, when the top callers to del_timer sync were
schedule_timeout and clear_timeout, the fix being the
del_single_shot_timer_sync patch,  with the knowledge that
schedule_timeout and clear_timeout do not create timers that re-add
themselves. This may not be enough, the problem is that schedule_timeout
at most times will call del_single_shot_timer_sync after the timer has
expired. This will cause del_timer to asume that the handler is running
on some cpu and del_timer_sync will still get invoked. Ofcourse, it also
means that del_timer_sync will continue to be a hotspot as far as taking
up cpu time is concerned.
	To confirm whether timers are mostly getting deleted before they expire
or after, I profiled the kernel, running a postgres load, logging
occurances of timer deletions before they expired and timer deletions
after they expired. The results show that the ratio of timers being
deleted after expiry to timers being deleted before expiry was 10:1.
This profiling was only done for schedule_timeout since it is the most
frequent caller to del_timer_singleshot_sync. There were 10000 occurance
of timers being deleted after expiry from schedule_timeout and 997
occurances of timers being deleted before expiry from schedule_timout, 
while the postgress workload ran. The ratio was always 10:1 from the
start of the workload to end as the number of deletions climbed. The
del_timer_singleshot_sync improves performance for the case where timers
are deleted before expiry but not for the case of timers being deleted
after expiry. The profiling data shows that the most frequesnt
occurance, is that of timers being deleted after expiry, to the ratio of
10:1. In such a case del_timer_singleshot_sync may not provide the
needed performance gain.

I tried Geoff's patch and it does seem to improve performance. Has
anyone else seen del_timer_sync as a hotspot after the
del_singleshot_timer_sync patch?

Re: [RFC] [PATCH] Performance of del_single_shot_timer_sync

[Andrew Morton]

shobhit dayal <shobhit@calsoftinc.com> wrote:
>
> I tried Geoff's patch and it does seem to improve performance.

By how much?  (CPU load, overall runtime, etc)

It's a bit odd to have an expired-timer-intensive workload.  Presumably
postgres has some short-lived nanosleep or select-based polling loop in
there which isn't doing much.

Re: [RFC] [PATCH] Performance of del_single_shot_timer_sync

[shobhit dayal]

Andrew Morton wrote:
> By how much?  (CPU load, overall runtime, etc)
> 
> It's a bit odd to have an expired-timer-intensive workload.  Presumably
> postgres has some short-lived nanosleep or select-based polling loop in
> there which isn't doing much.

I am running this load on a numa hardware so I profile the kernel by logging
functions that cause remote node memory access. I generate a final log
that shows functions that cause remote memory accesses greater that 0.5%
of all remote memory access on the system.

del_timer_sync was responsible for about 2% of all remote memory
accesses on the system and came up as part of the top 10 functions who
were doing this. On top was schedule(7.52%) followed by
default_wake_function(2.79%). Rest every one in the top 10 were
around the range of 2%.

After the patch it never came up in the logs again( so less than 0.5% of
all faulting eip's).


regards
shobhit


> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at  http://www.tux.org/lkml/
> 
> 
> 
> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at  http://www.tux.org/lkml/
> 

Re: [RFC] [PATCH] Performance of del_single_shot_timer_sync

[Andrew Morton]

shobhit dayal <shobhit@calsoftinc.com> wrote:
>
> Andrew Morton wrote:
> > By how much?  (CPU load, overall runtime, etc)
> > 
> > It's a bit odd to have an expired-timer-intensive workload.  Presumably
> > postgres has some short-lived nanosleep or select-based polling loop in
> > there which isn't doing much.
> 
> I am running this load on a numa hardware so I profile the kernel by logging
> functions that cause remote node memory access. I generate a final log
> that shows functions that cause remote memory accesses greater that 0.5%
> of all remote memory access on the system.
> 
> del_timer_sync was responsible for about 2% of all remote memory
> accesses on the system and came up as part of the top 10 functions who
> were doing this. On top was schedule(7.52%) followed by
> default_wake_function(2.79%). Rest every one in the top 10 were
> around the range of 2%.
> 
> After the patch it never came up in the logs again( so less than 0.5% of
> all faulting eip's).
> 

And what is the overall improvement from the del_timer_sync speedup patch? 
I mean: overall runtime and CPU time improvements for a
relatively-real-world benchmark?

Re: [RFC] [PATCH] Performance of del_single_shot_timer_sync

[shobhit dayal]

On Fri, 2004-10-08 at 22:49, Andrew Morton wrote:
> shobhit dayal <shobhit@calsoftinc.com> wrote:
> > 
> > del_timer_sync was responsible for about 2% of all remote memory
> > accesses on the system and came up as part of the top 10 functions who
> > were doing this. On top was schedule(7.52%) followed by
> > default_wake_function(2.79%). Rest every one in the top 10 were
> > around the range of 2%.
> > 
> > After the patch it never came up in the logs again( so less than 0.5% of
> > all faulting eip's).
> > 
> 
> And what is the overall improvement from the del_timer_sync speedup patch? 
> I mean: overall runtime and CPU time improvements for a
> relatively-real-world benchmark?
> 

I have Geoff's figures 

Before:             32p     4p
     Warm cache   29,000    505
     Cold cache   37,800   1220

After:              32p     4p
     Warm cache       95     88
     Cold cache    1,800    140
[Measurements are CPU cycles spent in a call to del_timer_sync, the average
of 1000 calls. 32p is 16-node NUMA, 4p is SMP.]

These figures, would apply for the case for where del_timer_sync does get called from del_single_shot_timer_sync.
That is del_singe_shot_timer_sync gets called after timer has expired

For my profiling workload i used the standard pg_regress module from the postgres installation and noticed that
the ratio of calls to del_single_shot_timer_sync after expiry to before expiry was 10:1. over 11000 calls to
del_single_shot_timer_sync.

regards
shobhit