Subject: Re: Scalability of interface creation and deletion

From: "Paul E. McKenney" <[email-masked]>
Date: Sun, 8 May 2011 06:44:25 -0700

On Sun, May 08, 2011 at 02:13:30PM +0100, Alex Bligh wrote:
> 
> >>The fact that increasing HZ masks the problem seems to imply that
> >>sychronize_sched() is waiting when it shouldn't be, as it suggests
> >>it's waiting for a context switch. But surely it shouldn't be
> >>waiting for context switch if all other cpu cores are idle?
> >>It knows that it (the caller) doesn't hold an rcu_read_lock,
> >>and presumably can see the other cpus are in the idle state,
> >>in which case surely it should return immediately? Distribution
> >>of latency in synchronize_sched() looks like this:
> >>
> >>20-49 us 110 instances (27.500%)
> >>50-99 us 45 instances (11.250%)
> >
> >Really?  I am having a hard time believing this above two.  Is this really
> >2000-4999 us and 5000-9999 us?  That would be much more believable,
> >and expected on a busy system with lots of context switching.  Or on a
> >system with CONFIG_NO_HZ=n.
> 
> Yes, really 20-49us and 50-99us, not ms. Raw data attached :-)
> 
> I'm guessing there are circumstances where there is an early exit.

Well, if you were onlining and offlining CPUs, then if there was only
one CPU online, this could happen.  And there really is only one CPU
online during boot, so if your measurements included early boot time,
this could easily explain these very short timings.

> $ fgrep HZ .config
> CONFIG_RCU_FAST_NO_HZ=y
> CONFIG_NO_HZ=y
> CONFIG_HZ_100=y
> # CONFIG_HZ_250 is not set
> # CONFIG_HZ_300 is not set
> # CONFIG_HZ_1000 is not set
> CONFIG_HZ=100
> # CONFIG_MACHZ_WDT is not set
> 
> >
> >>5000-9999 us 5 instances (1.250%)
> >
> >This makes sense for a mostly-idle system with frequent short bursts
> >of work.
> >
> >>10000-19999 us 33 instances (8.250%)
> >
> >This makes sense for a CONFIG_NO_HZ system that is idle, where there
> >is some amount of background work that is also using RCU grace periods.
> >
> >>20000-49999 us 4 instances (1.000%)
> >>50000-99999 us 191 instances (47.750%)
> >>100000-199999 us 12 instances (3.000%)
> >
> >These last involve additional delays.  Possibilities include long-running
> >irq handlers, SMIs, or NMIs.
> 
> There is nothing much going on these systems (idle, no other users,
> just normal system daemons).

And normal system daemons might cause this, right?

> Note this is with CONFIG_HZ=100 (which is the Ubuntu default). I wonder
> if that means you need to scale your expactations by a factor if 10 (i.e.
> you'd expect 50000-99999 for "a mostly-idle system with frequent
> short bursts of work."

Indeed, I was thinking in terms of HZ=1000.

							Thanx, Paul

> Interestingly there are quite a few of these on boot up. If this
> is a CONFIG_HZ thing, then setting it to 1000 would probably take
> half a second off bootup time.
> 
> 
> -- 
> Alex Bligh
> 
> 
> May  8 09:47:31 nattytest kernel: [  177.030197] synchronize_sched()
> in 66921 us
> May  8 09:47:31 nattytest kernel: [  177.120085] synchronize_sched()
> in 89080 us
> May  8 09:47:31 nattytest kernel: [  177.190910] synchronize_sched()
> in 46 us
> May  8 09:47:31 nattytest kernel: [  177.210087] synchronize_sched()
> in 18686 us
> May  8 09:47:32 nattytest kernel: [  177.400080] synchronize_sched()
> in 110609 us
> May  8 09:47:32 nattytest kernel: [  177.480071] synchronize_sched()
> in 78550 us
> May  8 09:47:32 nattytest kernel: [  177.550119] synchronize_sched()
> in 19087 us
> May  8 09:47:32 nattytest kernel: [  177.551761] synchronize_sched()
> in 79 us
> May  8 09:47:32 nattytest kernel: [  177.670085] synchronize_sched()
> in 60616 us
> May  8 09:47:32 nattytest kernel: [  177.760075] synchronize_sched()
> in 88465 us
> May  8 09:47:32 nattytest kernel: [  177.820999] synchronize_sched()
> in 45 us
> May  8 09:47:32 nattytest kernel: [  177.840086] synchronize_sched()
> in 17579 us
> May  8 09:47:32 nattytest kernel: [  177.970084] synchronize_sched()
> in 70925 us
> May  8 09:47:32 nattytest kernel: [  178.050092] synchronize_sched()
> in 78477 us
> May  8 09:47:32 nattytest kernel: [  178.101046] synchronize_sched()
> in 39 us
> May  8 09:47:32 nattytest kernel: [  178.102574] synchronize_sched()
> in 48 us
> May  8 09:47:33 nattytest kernel: [  178.230082] synchronize_sched()
> in 70966 us
> May  8 09:47:33 nattytest kernel: [  178.310071] synchronize_sched()
> in 78503 us
> May  8 09:47:33 nattytest kernel: [  178.371056] synchronize_sched()
> in 43 us
> May  8 09:47:33 nattytest kernel: [  178.390094] synchronize_sched()
> in 17553 us
> May  8 09:47:33 nattytest kernel: [  178.540084] synchronize_sched()
> in 70533 us
> May  8 09:47:33 nattytest kernel: [  178.620074] synchronize_sched()
> in 79172 us
> May  8 09:47:33 nattytest kernel: [  178.671124] synchronize_sched()
> in 57 us
> May  8 09:47:33 nattytest kernel: [  178.672645] synchronize_sched()
> in 49 us
> May  8 09:47:33 nattytest kernel: [  178.830106] synchronize_sched()
> in 100955 us
> May  8 09:47:33 nattytest kernel: [  178.910084] synchronize_sched()
> in 78408 us
> May  8 09:47:33 nattytest kernel: [  178.961090] synchronize_sched()
> in 43 us
> May  8 09:47:33 nattytest kernel: [  178.962642] synchronize_sched()
> in 50 us
> May  8 09:47:33 nattytest kernel: [  179.090088] synchronize_sched()
> in 71354 us
> May  8 09:47:33 nattytest kernel: [  179.220071] synchronize_sched()
> in 128463 us
> May  8 09:47:34 nattytest kernel: [  179.300867] synchronize_sched()
> in 52 us
> May  8 09:47:34 nattytest kernel: [  179.302079] synchronize_sched()
> in 48 us
> May  8 09:47:34 nattytest kernel: [  179.420085] synchronize_sched()
> in 61562 us
> May  8 09:47:34 nattytest kernel: [  179.500093] synchronize_sched()
> in 78506 us
> May  8 09:47:34 nattytest kernel: [  179.551048] synchronize_sched()
> in 42 us
> May  8 09:47:34 nattytest kernel: [  179.552637] synchronize_sched()
> in 51 us
> May  8 09:47:34 nattytest kernel: [  179.670088] synchronize_sched()
> in 61469 us
> May  8 09:47:34 nattytest kernel: [  179.760078] synchronize_sched()
> in 88430 us
> May  8 09:47:34 nattytest kernel: [  179.830918] synchronize_sched()
> in 44 us
> May  8 09:47:34 nattytest kernel: [  179.850173] synchronize_sched()
> in 17783 us
> May  8 09:47:34 nattytest kernel: [  180.080085] synchronize_sched()
> in 150585 us
> May  8 09:47:34 nattytest kernel: [  180.160082] synchronize_sched()
> in 78381 us
> May  8 09:47:34 nattytest kernel: [  180.211027] synchronize_sched()
> in 39 us
> May  8 09:47:34 nattytest kernel: [  180.212186] synchronize_sched()
> in 52 us
> May  8 09:47:35 nattytest kernel: [  180.320091] synchronize_sched()
> in 50520 us
> May  8 09:47:35 nattytest kernel: [  180.400074] synchronize_sched()
> in 78525 us
> May  8 09:47:35 nattytest kernel: [  180.451028] synchronize_sched()
> in 50 us
> May  8 09:47:35 nattytest kernel: [  180.452100] synchronize_sched()
> in 30 us
> May  8 09:47:35 nattytest kernel: [  180.570086] synchronize_sched()
> in 61211 us
> May  8 09:47:35 nattytest kernel: [  180.650073] synchronize_sched()
> in 79145 us
> May  8 09:47:35 nattytest kernel: [  180.701376] synchronize_sched()
> in 38 us
> May  8 09:47:35 nattytest kernel: [  180.703490] synchronize_sched()
> in 57 us
> May  8 09:47:35 nattytest kernel: [  180.820087] synchronize_sched()
> in 61483 us
> May  8 09:47:35 nattytest kernel: [  180.910081] synchronize_sched()
> in 88485 us
> May  8 09:47:35 nattytest kernel: [  180.965970] synchronize_sched()
> in 49 us
> May  8 09:47:35 nattytest kernel: [  180.990091] synchronize_sched()
> in 22425 us
> May  8 09:47:35 nattytest kernel: [  181.150084] synchronize_sched()
> in 71317 us
> May  8 09:47:36 nattytest kernel: [  181.230074] synchronize_sched()
> in 78470 us
> May  8 09:47:36 nattytest kernel: [  181.300099] synchronize_sched()
> in 18988 us
> May  8 09:47:36 nattytest kernel: [  181.301637] synchronize_sched()
> in 46 us
> May  8 09:47:36 nattytest kernel: [  181.420086] synchronize_sched()
> in 61240 us
> May  8 09:47:36 nattytest kernel: [  181.500072] synchronize_sched()
> in 77682 us
> May  8 09:47:36 nattytest kernel: [  181.551059] synchronize_sched()
> in 45 us
> May  8 09:47:36 nattytest kernel: [  181.552546] synchronize_sched()
> in 29 us
> May  8 09:47:36 nattytest kernel: [  181.670084] synchronize_sched()
> in 61612 us
> May  8 09:47:36 nattytest kernel: [  181.750076] synchronize_sched()
> in 78513 us
> May  8 09:47:36 nattytest kernel: [  181.801195] synchronize_sched()
> in 52 us
> May  8 09:47:36 nattytest kernel: [  181.802805] synchronize_sched()
> in 69 us
> May  8 09:47:36 nattytest kernel: [  181.920088] synchronize_sched()
> in 61998 us
> May  8 09:47:36 nattytest kernel: [  182.000091] synchronize_sched()
> in 78539 us
> May  8 09:47:36 nattytest kernel: [  182.051053] synchronize_sched()
> in 42 us
> May  8 09:47:36 nattytest kernel: [  182.052595] synchronize_sched()
> in 29 us
> May  8 09:47:36 nattytest kernel: [  182.170103] synchronize_sched()
> in 61607 us
> May  8 09:47:37 nattytest kernel: [  182.260072] synchronize_sched()
> in 88460 us
> May  8 09:47:37 nattytest kernel: [  182.331028] synchronize_sched()
> in 44 us
> May  8 09:47:37 nattytest kernel: [  182.350096] synchronize_sched()
> in 17563 us
> May  8 09:47:37 nattytest kernel: [  182.500085] synchronize_sched()
> in 71793 us
> May  8 09:47:37 nattytest kernel: [  182.620085] synchronize_sched()
> in 118343 us
> May  8 09:47:37 nattytest kernel: [  182.671024] synchronize_sched()
> in 39 us
> May  8 09:47:37 nattytest kernel: [  182.672511] synchronize_sched()
> in 29 us
> May  8 09:47:37 nattytest kernel: [  182.830096] synchronize_sched()
> in 101470 us
> May  8 09:47:37 nattytest kernel: [  182.910081] synchronize_sched()
> in 78413 us
> May  8 09:47:37 nattytest kernel: [  182.971056] synchronize_sched()
> in 43 us
> May  8 09:47:37 nattytest kernel: [  182.972568] synchronize_sched()
> in 44 us
> May  8 09:47:37 nattytest kernel: [  183.100084] synchronize_sched()
> in 60854 us
> May  8 09:47:37 nattytest kernel: [  183.170097] synchronize_sched()
> in 68450 us
> May  8 09:47:37 nattytest kernel: [  183.221081] synchronize_sched()
> in 40 us
> May  8 09:47:37 nattytest kernel: [  183.222580] synchronize_sched()
> in 29 us
> May  8 09:47:38 nattytest kernel: [  183.340082] synchronize_sched()
> in 61422 us
> May  8 09:47:38 nattytest kernel: [  183.420078] synchronize_sched()
> in 79154 us
> May  8 09:47:38 nattytest kernel: [  183.471003] synchronize_sched()
> in 41 us
> May  8 09:47:38 nattytest kernel: [  183.472469] synchronize_sched()
> in 29 us
> May  8 09:47:38 nattytest kernel: [  183.590095] synchronize_sched()
> in 61591 us
> May  8 09:47:38 nattytest kernel: [  183.670069] synchronize_sched()
> in 78533 us
> May  8 09:47:38 nattytest kernel: [  183.721106] synchronize_sched()
> in 43 us
> May  8 09:47:38 nattytest kernel: [  183.722663] synchronize_sched()
> in 49 us
> May  8 09:47:38 nattytest kernel: [  183.850094] synchronize_sched()
> in 71060 us
> May  8 09:47:38 nattytest kernel: [  183.930080] synchronize_sched()
> in 78522 us
> May  8 09:47:38 nattytest kernel: [  183.981040] synchronize_sched()
> in 44 us
> May  8 09:47:38 nattytest kernel: [  183.990375] synchronize_sched()
> in 7913 us
> May  8 09:47:38 nattytest kernel: [  184.150080] synchronize_sched()
> in 81568 us
> May  8 09:47:38 nattytest kernel: [  184.220088] synchronize_sched()
> in 68481 us
> May  8 09:47:39 nattytest kernel: [  184.281161] synchronize_sched()
> in 65 us
> May  8 09:47:39 nattytest kernel: [  184.282733] synchronize_sched()
> in 60 us
> May  8 09:47:39 nattytest kernel: [  184.400079] synchronize_sched()
> in 61791 us
> May  8 09:47:39 nattytest kernel: [  184.480104] synchronize_sched()
> in 79181 us
> May  8 09:47:39 nattytest kernel: [  184.550103] synchronize_sched()
> in 19063 us
> May  8 09:47:39 nattytest kernel: [  184.551621] synchronize_sched()
> in 30 us
> May  8 09:47:39 nattytest kernel: [  184.680083] synchronize_sched()
> in 71800 us
> May  8 09:47:39 nattytest kernel: [  184.750084] synchronize_sched()
> in 69162 us
> May  8 09:47:39 nattytest kernel: [  184.801153] synchronize_sched()
> in 51 us
> May  8 09:47:39 nattytest kernel: [  184.802802] synchronize_sched()
> in 53 us
> May  8 09:47:39 nattytest kernel: [  184.920091] synchronize_sched()
> in 61217 us
> May  8 09:47:39 nattytest kernel: [  185.000074] synchronize_sched()
> in 79141 us
> May  8 09:47:39 nattytest kernel: [  185.050985] synchronize_sched()
> in 40 us
> May  8 09:47:39 nattytest kernel: [  185.052727] synchronize_sched()
> in 47 us
> May  8 09:47:39 nattytest kernel: [  185.170087] synchronize_sched()
> in 62802 us
> May  8 09:47:40 nattytest kernel: [  185.250074] synchronize_sched()
> in 78418 us
> May  8 09:47:40 nattytest kernel: [  185.311022] synchronize_sched()
> in 40 us
> May  8 09:47:40 nattytest kernel: [  185.312542] synchronize_sched()
> in 63 us
> May  8 09:47:40 nattytest kernel: [  185.430111] synchronize_sched()
> in 61894 us
> May  8 09:47:40 nattytest kernel: [  185.510073] synchronize_sched()
> in 78410 us
> May  8 09:47:40 nattytest kernel: [  185.561055] synchronize_sched()
> in 58 us
> May  8 09:47:40 nattytest kernel: [  185.562589] synchronize_sched()
> in 45 us
> May  8 09:47:40 nattytest kernel: [  185.680091] synchronize_sched()
> in 62023 us
> May  8 09:47:40 nattytest kernel: [  185.760076] synchronize_sched()
> in 78438 us
> May  8 09:47:40 nattytest kernel: [  185.811063] synchronize_sched()
> in 45 us
> May  8 09:47:40 nattytest kernel: [  185.812580] synchronize_sched()
> in 52 us
> May  8 09:47:40 nattytest kernel: [  185.930089] synchronize_sched()
> in 61864 us
> May  8 09:47:40 nattytest kernel: [  186.010072] synchronize_sched()
> in 78465 us
> May  8 09:47:40 nattytest kernel: [  186.061141] synchronize_sched()
> in 44 us
> May  8 09:47:40 nattytest kernel: [  186.062631] synchronize_sched()
> in 29 us
> May  8 09:47:40 nattytest kernel: [  186.180078] synchronize_sched()
> in 61806 us
> May  8 09:47:41 nattytest kernel: [  186.260074] synchronize_sched()
> in 78415 us
> May  8 09:47:41 nattytest kernel: [  186.311073] synchronize_sched()
> in 43 us
> May  8 09:47:41 nattytest kernel: [  186.312573] synchronize_sched()
> in 29 us
> May  8 09:47:41 nattytest kernel: [  186.440083] synchronize_sched()
> in 72358 us
> May  8 09:47:41 nattytest kernel: [  186.520071] synchronize_sched()
> in 78395 us
> May  8 09:47:41 nattytest kernel: [  186.573068] synchronize_sched()
> in 66 us
> May  8 09:47:41 nattytest kernel: [  186.590105] synchronize_sched()
> in 15551 us
> May  8 09:47:41 nattytest kernel: [  186.740092] synchronize_sched()
> in 71884 us
> May  8 09:47:41 nattytest kernel: [  186.830069] synchronize_sched()
> in 89123 us
> May  8 09:47:41 nattytest kernel: [  186.890967] synchronize_sched()
> in 41 us
> May  8 09:47:41 nattytest kernel: [  186.910091] synchronize_sched()
> in 18639 us
> May  8 09:47:41 nattytest kernel: [  187.070078] synchronize_sched()
> in 82847 us
> May  8 09:47:41 nattytest kernel: [  187.140090] synchronize_sched()
> in 68499 us
> May  8 09:47:41 nattytest kernel: [  187.191148] synchronize_sched()
> in 57 us
> May  8 09:47:41 nattytest kernel: [  187.192743] synchronize_sched()
> in 69 us
> May  8 09:47:42 nattytest kernel: [  187.310087] synchronize_sched()
> in 63069 us
> May  8 09:47:42 nattytest kernel: [  187.400076] synchronize_sched()
> in 88432 us
> May  8 09:47:42 nattytest kernel: [  187.461521] synchronize_sched()
> in 57 us
> May  8 09:47:42 nattytest kernel: [  187.480099] synchronize_sched()
> in 16493 us
> May  8 09:47:42 nattytest kernel: [  187.640081] synchronize_sched()
> in 82269 us
> May  8 09:47:42 nattytest kernel: [  187.710079] synchronize_sched()
> in 68389 us
> May  8 09:47:42 nattytest kernel: [  187.761071] synchronize_sched()
> in 38 us
> May  8 09:47:42 nattytest kernel: [  187.762623] synchronize_sched()
> in 67 us
> May  8 09:47:42 nattytest kernel: [  187.880077] synchronize_sched()
> in 61847 us
> May  8 09:47:42 nattytest kernel: [  187.960096] synchronize_sched()
> in 78450 us
> May  8 09:47:42 nattytest kernel: [  188.011147] synchronize_sched()
> in 62 us
> May  8 09:47:42 nattytest kernel: [  188.012617] synchronize_sched()
> in 29 us
> May  8 09:47:42 nattytest kernel: [  188.130083] synchronize_sched()
> in 62431 us
> May  8 09:47:42 nattytest kernel: [  188.210090] synchronize_sched()
> in 78447 us
> May  8 09:47:43 nattytest kernel: [  188.261015] synchronize_sched()
> in 38 us
> May  8 09:47:43 nattytest kernel: [  188.262491] synchronize_sched()
> in 29 us
> May  8 09:47:43 nattytest kernel: [  188.380097] synchronize_sched()
> in 61923 us
> May  8 09:47:43 nattytest kernel: [  188.470131] synchronize_sched()
> in 88521 us
> May  8 09:47:43 nattytest kernel: [  188.531024] synchronize_sched()
> in 46 us
> May  8 09:47:43 nattytest kernel: [  188.550087] synchronize_sched()
> in 17676 us
> May  8 09:47:43 nattytest kernel: [  188.690085] synchronize_sched()
> in 71911 us
> May  8 09:47:43 nattytest kernel: [  188.820071] synchronize_sched()
> in 128473 us
> May  8 09:47:43 nattytest kernel: [  188.881032] synchronize_sched()
> in 42 us
> May  8 09:47:43 nattytest kernel: [  188.900085] synchronize_sched()
> in 17588 us
> May  8 09:47:43 nattytest kernel: [  189.080084] synchronize_sched()
> in 111945 us
> May  8 09:47:43 nattytest kernel: [  189.170068] synchronize_sched()
> in 88449 us
> May  8 09:47:43 nattytest kernel: [  189.221066] synchronize_sched()
> in 41 us
> May  8 09:47:44 nattytest kernel: [  189.230257] synchronize_sched()
> in 7463 us
> May  8 09:47:44 nattytest kernel: [  189.380093] synchronize_sched()
> in 71896 us
> May  8 09:47:44 nattytest kernel: [  189.470093] synchronize_sched()
> in 88481 us
> May  8 09:47:44 nattytest kernel: [  189.550883] synchronize_sched()
> in 43 us
> May  8 09:47:44 nattytest kernel: [  189.552391] synchronize_sched()
> in 29 us
> May  8 09:47:44 nattytest kernel: [  189.670085] synchronize_sched()
> in 61850 us
> May  8 09:47:44 nattytest kernel: [  189.760080] synchronize_sched()
> in 88549 us
> May  8 09:47:44 nattytest kernel: [  189.821014] synchronize_sched()
> in 44 us
> May  8 09:47:44 nattytest kernel: [  189.850080] synchronize_sched()
> in 27628 us
> May  8 09:47:44 nattytest kernel: [  189.990087] synchronize_sched()
> in 72251 us
> May  8 09:47:44 nattytest kernel: [  190.080074] synchronize_sched()
> in 88486 us
> May  8 09:47:44 nattytest kernel: [  190.150968] synchronize_sched()
> in 71 us
> May  8 09:47:44 nattytest kernel: [  190.170092] synchronize_sched()
> in 17672 us
> May  8 09:47:45 nattytest kernel: [  190.320088] synchronize_sched()
> in 71937 us
> May  8 09:47:45 nattytest kernel: [  190.410068] synchronize_sched()
> in 89155 us
> May  8 09:47:45 nattytest kernel: [  190.490882] synchronize_sched()
> in 40 us
> May  8 09:47:45 nattytest kernel: [  190.492405] synchronize_sched()
> in 29 us
> May  8 09:47:45 nattytest kernel: [  190.620103] synchronize_sched()
> in 62808 us
> May  8 09:47:45 nattytest kernel: [  190.700108] synchronize_sched()
> in 78486 us
> May  8 09:47:45 nattytest kernel: [  190.820119] synchronize_sched()
> in 69075 us
> May  8 09:47:45 nattytest kernel: [  190.870096] synchronize_sched()
> in 48447 us
> May  8 09:47:45 nattytest kernel: [  191.000082] synchronize_sched()
> in 62795 us
> May  8 09:47:45 nattytest kernel: [  191.080082] synchronize_sched()
> in 78489 us
> May  8 09:47:45 nattytest kernel: [  191.141021] synchronize_sched()
> in 61 us
> May  8 09:47:45 nattytest kernel: [  191.160086] synchronize_sched()
> in 17596 us
> May  8 09:47:46 nattytest kernel: [  191.310097] synchronize_sched()
> in 82089 us
> May  8 09:47:46 nattytest kernel: [  191.390076] synchronize_sched()
> in 78427 us
> May  8 09:47:46 nattytest kernel: [  191.451045] synchronize_sched()
> in 49 us
> May  8 09:47:46 nattytest kernel: [  191.470088] synchronize_sched()
> in 17643 us
> May  8 09:47:46 nattytest kernel: [  191.620095] synchronize_sched()
> in 72871 us
> May  8 09:47:46 nattytest kernel: [  191.700072] synchronize_sched()
> in 79137 us
> May  8 09:47:46 nattytest kernel: [  191.751087] synchronize_sched()
> in 40 us
> May  8 09:47:46 nattytest kernel: [  191.752600] synchronize_sched()
> in 48 us
> May  8 09:47:46 nattytest kernel: [  191.880092] synchronize_sched()
> in 72297 us
> May  8 09:47:46 nattytest kernel: [  191.950076] synchronize_sched()
> in 69142 us
> May  8 09:47:46 nattytest kernel: [  192.005349] synchronize_sched()
> in 54 us
> May  8 09:47:46 nattytest kernel: [  192.006834] synchronize_sched()
> in 30 us
> May  8 09:47:46 nattytest kernel: [  192.130091] synchronize_sched()
> in 72839 us
> May  8 09:47:46 nattytest kernel: [  192.210069] synchronize_sched()
> in 78535 us
> May  8 09:47:47 nattytest kernel: [  192.270973] synchronize_sched()
> in 43 us
> May  8 09:47:47 nattytest kernel: [  192.300094] synchronize_sched()
> in 27592 us
> May  8 09:47:47 nattytest kernel: [  192.450079] synchronize_sched()
> in 83072 us
> May  8 09:47:47 nattytest kernel: [  192.520073] synchronize_sched()
> in 68499 us
> May  8 09:47:47 nattytest kernel: [  192.571106] synchronize_sched()
> in 44 us
> May  8 09:47:47 nattytest kernel: [  192.572585] synchronize_sched()
> in 29 us
> May  8 09:47:47 nattytest kernel: [  192.700080] synchronize_sched()
> in 62670 us
> May  8 09:47:47 nattytest kernel: [  192.820084] synchronize_sched()
> in 118509 us
> May  8 09:47:47 nattytest kernel: [  192.871107] synchronize_sched()
> in 69 us
> May  8 09:47:47 nattytest kernel: [  192.872611] synchronize_sched()
> in 29 us
> May  8 09:47:47 nattytest kernel: [  192.990110] synchronize_sched()
> in 62742 us
> May  8 09:47:47 nattytest kernel: [  193.080070] synchronize_sched()
> in 89147 us
> May  8 09:47:47 nattytest kernel: [  193.150962] synchronize_sched()
> in 65 us
> May  8 09:47:47 nattytest kernel: [  193.160285] synchronize_sched()
> in 8879 us
> May  8 09:47:48 nattytest kernel: [  193.300097] synchronize_sched()
> in 72753 us
> May  8 09:47:48 nattytest kernel: [  193.380075] synchronize_sched()
> in 78472 us
> May  8 09:47:48 nattytest kernel: [  193.431029] synchronize_sched()
> in 41 us
> May  8 09:47:48 nattytest kernel: [  193.432518] synchronize_sched()
> in 30 us
> May  8 09:47:48 nattytest kernel: [  193.560081] synchronize_sched()
> in 72448 us
> May  8 09:47:48 nattytest kernel: [  193.670073] synchronize_sched()
> in 108452 us
> May  8 09:47:48 nattytest kernel: [  193.721098] synchronize_sched()
> in 49 us
> May  8 09:47:48 nattytest kernel: [  193.722821] synchronize_sched()
> in 30 us
> May  8 09:47:48 nattytest kernel: [  193.840075] synchronize_sched()
> in 62317 us
> May  8 09:47:48 nattytest kernel: [  193.920070] synchronize_sched()
> in 78472 us
> May  8 09:47:48 nattytest kernel: [  193.971073] synchronize_sched()
> in 43 us
> May  8 09:47:48 nattytest kernel: [  193.972550] synchronize_sched()
> in 29 us
> May  8 09:47:48 nattytest kernel: [  194.100088] synchronize_sched()
> in 72391 us
> May  8 09:47:48 nattytest kernel: [  194.170082] synchronize_sched()
> in 69202 us
> May  8 09:47:48 nattytest kernel: [  194.221053] synchronize_sched()
> in 40 us
> May  8 09:47:48 nattytest kernel: [  194.222543] synchronize_sched()
> in 29 us
> May  8 09:47:49 nattytest kernel: [  194.350082] synchronize_sched()
> in 72874 us
> May  8 09:47:49 nattytest kernel: [  194.430068] synchronize_sched()
> in 78536 us
> May  8 09:47:49 nattytest kernel: [  194.481167] synchronize_sched()
> in 70 us
> May  8 09:47:49 nattytest kernel: [  194.500091] synchronize_sched()
> in 17486 us
> May  8 09:47:49 nattytest kernel: [  194.640088] synchronize_sched()
> in 73012 us
> May  8 09:47:49 nattytest kernel: [  194.730069] synchronize_sched()
> in 88519 us
> May  8 09:47:49 nattytest kernel: [  194.781117] synchronize_sched()
> in 46 us
> May  8 09:47:49 nattytest kernel: [  194.792950] synchronize_sched()
> in 10384 us
> May  8 09:47:49 nattytest kernel: [  194.910126] synchronize_sched()
> in 63131 us
> May  8 09:47:49 nattytest kernel: [  195.000088] synchronize_sched()
> in 88453 us
> May  8 09:47:49 nattytest kernel: [  195.160080] synchronize_sched()
> in 79582 us
> May  8 09:47:50 nattytest kernel: [  195.240073] synchronize_sched()
> in 79132 us
> May  8 09:47:50 nattytest kernel: [  195.360124] synchronize_sched()
> in 62368 us
> May  8 09:47:50 nattytest kernel: [  195.440096] synchronize_sched()
> in 79148 us
> May  8 09:47:50 nattytest kernel: [  195.491063] synchronize_sched()
> in 53 us
> May  8 09:47:50 nattytest kernel: [  195.492182] synchronize_sched()
> in 29 us
> May  8 09:47:50 nattytest kernel: [  195.610085] synchronize_sched()
> in 62444 us
> May  8 09:47:50 nattytest kernel: [  195.700078] synchronize_sched()
> in 89170 us
> May  8 09:47:50 nattytest kernel: [  195.761011] synchronize_sched()
> in 57 us
> May  8 09:47:50 nattytest kernel: [  195.780137] synchronize_sched()
> in 18587 us
> May  8 09:47:50 nattytest kernel: [  195.920080] synchronize_sched()
> in 73194 us
> May  8 09:47:50 nattytest kernel: [  196.000073] synchronize_sched()
> in 78456 us
> May  8 09:47:50 nattytest kernel: [  196.051067] synchronize_sched()
> in 42 us
> May  8 09:47:50 nattytest kernel: [  196.052613] synchronize_sched()
> in 44 us
> May  8 09:47:50 nattytest kernel: [  196.170080] synchronize_sched()
> in 63040 us
> May  8 09:47:51 nattytest kernel: [  196.250075] synchronize_sched()
> in 78420 us
> May  8 09:47:51 nattytest kernel: [  196.301051] synchronize_sched()
> in 46 us
> May  8 09:47:51 nattytest kernel: [  196.302527] synchronize_sched()
> in 29 us
> May  8 09:47:51 nattytest kernel: [  196.420095] synchronize_sched()
> in 62701 us
> May  8 09:47:51 nattytest kernel: [  196.500064] synchronize_sched()
> in 78448 us
> May  8 09:47:51 nattytest kernel: [  196.551104] synchronize_sched()
> in 48 us
> May  8 09:47:51 nattytest kernel: [  196.552631] synchronize_sched()
> in 49 us
> May  8 09:47:51 nattytest kernel: [  196.670084] synchronize_sched()
> in 63111 us
> May  8 09:47:51 nattytest kernel: [  196.750095] synchronize_sched()
> in 78464 us
> May  8 09:47:51 nattytest kernel: [  196.801082] synchronize_sched()
> in 60 us
> May  8 09:47:51 nattytest kernel: [  196.802616] synchronize_sched()
> in 43 us
> May  8 09:47:51 nattytest kernel: [  196.930124] synchronize_sched()
> in 73010 us
> May  8 09:47:51 nattytest kernel: [  197.010084] synchronize_sched()
> in 78359 us
> May  8 09:47:51 nattytest kernel: [  197.071137] synchronize_sched()
> in 79 us
> May  8 09:47:51 nattytest kernel: [  197.080320] synchronize_sched()
> in 7773 us
> May  8 09:47:52 nattytest kernel: [  197.230086] synchronize_sched()
> in 83245 us
> May  8 09:47:52 nattytest kernel: [  197.310075] synchronize_sched()
> in 78509 us
> May  8 09:47:52 nattytest kernel: [  197.361050] synchronize_sched()
> in 44 us
> May  8 09:47:52 nattytest kernel: [  197.380084] synchronize_sched()
> in 17591 us
> May  8 09:47:52 nattytest kernel: [  197.530084] synchronize_sched()
> in 82999 us
> May  8 09:47:52 nattytest kernel: [  197.610080] synchronize_sched()
> in 79162 us
> May  8 09:47:52 nattytest kernel: [  197.680937] synchronize_sched()
> in 65 us
> May  8 09:47:52 nattytest kernel: [  197.700096] synchronize_sched()
> in 18620 us
> May  8 09:47:52 nattytest kernel: [  197.850141] synchronize_sched()
> in 73601 us
> May  8 09:47:52 nattytest kernel: [  197.930091] synchronize_sched()
> in 78393 us
> May  8 09:47:52 nattytest kernel: [  197.981050] synchronize_sched()
> in 39 us
> May  8 09:47:52 nattytest kernel: [  197.982788] synchronize_sched()
> in 29 us
> May  8 09:47:52 nattytest kernel: [  198.110084] synchronize_sched()
> in 72893 us
> May  8 09:47:52 nattytest kernel: [  198.180072] synchronize_sched()
> in 69151 us
> May  8 09:47:53 nattytest kernel: [  198.231098] synchronize_sched()
> in 50 us
> May  8 09:47:53 nattytest kernel: [  198.232679] synchronize_sched()
> in 46 us
> May  8 09:47:53 nattytest kernel: [  198.370084] synchronize_sched()
> in 72935 us
> May  8 09:47:53 nattytest kernel: [  198.450068] synchronize_sched()
> in 78461 us
> May  8 09:47:53 nattytest kernel: [  198.511077] synchronize_sched()
> in 77 us
> May  8 09:47:53 nattytest kernel: [  198.530094] synchronize_sched()
> in 17512 us
> May  8 09:47:53 nattytest kernel: [  198.670095] synchronize_sched()
> in 83122 us
> May  8 09:47:53 nattytest kernel: [  198.740079] synchronize_sched()
> in 68453 us
> May  8 09:47:53 nattytest kernel: [  198.801121] synchronize_sched()
> in 48 us
> May  8 09:47:53 nattytest kernel: [  198.802600] synchronize_sched()
> in 29 us
> May  8 09:47:53 nattytest kernel: [  198.920100] synchronize_sched()
> in 63392 us
> May  8 09:47:53 nattytest kernel: [  199.000088] synchronize_sched()
> in 78482 us
> May  8 09:47:53 nattytest kernel: [  199.070099] synchronize_sched()
> in 19013 us
> May  8 09:47:53 nattytest kernel: [  199.071626] synchronize_sched()
> in 48 us
> May  8 09:47:53 nattytest kernel: [  199.190083] synchronize_sched()
> in 63245 us
> May  8 09:47:54 nattytest kernel: [  199.270075] synchronize_sched()
> in 78491 us
> May  8 09:47:54 nattytest kernel: [  199.321088] synchronize_sched()
> in 42 us
> May  8 09:47:54 nattytest kernel: [  199.322589] synchronize_sched()
> in 29 us
> May  8 09:47:54 nattytest kernel: [  199.440101] synchronize_sched()
> in 63063 us
> May  8 09:47:54 nattytest kernel: [  199.520073] synchronize_sched()
> in 78463 us
> May  8 09:47:54 nattytest kernel: [  199.571056] synchronize_sched()
> in 49 us
> May  8 09:47:54 nattytest kernel: [  199.572488] synchronize_sched()
> in 29 us
> May  8 09:47:54 nattytest kernel: [  199.700083] synchronize_sched()
> in 73220 us
> May  8 09:47:54 nattytest kernel: [  199.770096] synchronize_sched()
> in 68508 us
> May  8 09:47:54 nattytest kernel: [  199.821090] synchronize_sched()
> in 50 us
> May  8 09:47:54 nattytest kernel: [  199.822540] synchronize_sched()
> in 29 us
> May  8 09:47:54 nattytest kernel: [  199.940084] synchronize_sched()
> in 63681 us
> May  8 09:47:54 nattytest kernel: [  200.020067] synchronize_sched()
> in 78451 us
> May  8 09:47:54 nattytest kernel: [  200.071095] synchronize_sched()
> in 41 us
> May  8 09:47:54 nattytest kernel: [  200.072566] synchronize_sched()
> in 29 us
> May  8 09:47:54 nattytest kernel: [  200.190089] synchronize_sched()
> in 63584 us
> May  8 09:47:55 nattytest kernel: [  200.280076] synchronize_sched()
> in 89123 us
> May  8 09:47:55 nattytest kernel: [  200.341011] synchronize_sched()
> in 61 us
> May  8 09:47:55 nattytest kernel: [  200.360094] synchronize_sched()
> in 18527 us
> May  8 09:47:55 nattytest kernel: [  200.520085] synchronize_sched()
> in 94129 us
> May  8 09:47:55 nattytest kernel: [  200.670072] synchronize_sched()
> in 148512 us
> May  8 09:47:55 nattytest kernel: [  200.730983] synchronize_sched()
> in 41 us
> May  8 09:47:55 nattytest kernel: [  200.750355] synchronize_sched()
> in 17917 us
> May  8 09:47:55 nattytest kernel: [  200.890082] synchronize_sched()
> in 83406 us
> May  8 09:47:55 nattytest kernel: [  200.970072] synchronize_sched()
> in 78439 us
> May  8 09:47:55 nattytest kernel: [  201.031034] synchronize_sched()
> in 45 us
> May  8 09:47:55 nattytest kernel: [  201.050090] synchronize_sched()
> in 17555 us
> May  8 09:47:55 nattytest kernel: [  201.200090] synchronize_sched()
> in 83318 us
> May  8 09:47:56 nattytest kernel: [  201.270075] synchronize_sched()
> in 68468 us
> May  8 09:47:56 nattytest kernel: [  201.330983] synchronize_sched()
> in 41 us
> May  8 09:47:56 nattytest kernel: [  201.332487] synchronize_sched()
> in 62 us
> May  8 09:47:56 nattytest kernel: [  201.450088] synchronize_sched()
> in 53772 us
> May  8 09:47:56 nattytest kernel: [  201.530075] synchronize_sched()
> in 78437 us
> May  8 09:47:56 nattytest kernel: [  201.590986] synchronize_sched()
> in 46 us
> May  8 09:47:56 nattytest kernel: [  201.592134] synchronize_sched()
> in 29 us
> May  8 09:47:56 nattytest kernel: [  201.710085] synchronize_sched()
> in 63551 us
> May  8 09:47:56 nattytest kernel: [  201.830146] synchronize_sched()
> in 118553 us
> May  8 09:47:56 nattytest kernel: [  201.891143] synchronize_sched()
> in 50 us
> May  8 09:47:56 nattytest kernel: [  201.892712] synchronize_sched()
> in 55 us
> May  8 09:47:56 nattytest kernel: [  202.010092] synchronize_sched()
> in 63446 us
> May  8 09:47:56 nattytest kernel: [  202.090126] synchronize_sched()
> in 78477 us
> May  8 09:47:56 nattytest kernel: [  202.141120] synchronize_sched()
> in 45 us
> May  8 09:47:56 nattytest kernel: [  202.142867] synchronize_sched()
> in 30 us
> May  8 09:47:57 nattytest kernel: [  202.260092] synchronize_sched()
> in 63271 us
> May  8 09:47:57 nattytest kernel: [  202.340071] synchronize_sched()
> in 78474 us
> May  8 09:47:57 nattytest kernel: [  202.391094] synchronize_sched()
> in 44 us
> May  8 09:47:57 nattytest kernel: [  202.392581] synchronize_sched()
> in 29 us
> May  8 09:47:57 nattytest kernel: [  202.510110] synchronize_sched()
> in 63718 us
> May  8 09:47:57 nattytest kernel: [  202.600092] synchronize_sched()
> in 88434 us
> May  8 09:47:57 nattytest kernel: [  202.661075] synchronize_sched()
> in 46 us
> May  8 09:47:57 nattytest kernel: [  202.680091] synchronize_sched()
> in 17516 us
> May  8 09:47:57 nattytest kernel: [  202.820083] synchronize_sched()
> in 83733 us
> May  8 09:47:57 nattytest kernel: [  202.900067] synchronize_sched()
> in 78478 us
> May  8 09:47:57 nattytest kernel: [  202.951062] synchronize_sched()
> in 43 us
> May  8 09:47:57 nattytest kernel: [  202.960445] synchronize_sched()
> in 7921 us
> May  8 09:47:57 nattytest kernel: [  203.100080] synchronize_sched()
> in 83496 us
> May  8 09:47:57 nattytest kernel: [  203.170084] synchronize_sched()
> in 68474 us
> May  8 09:47:57 nattytest kernel: [  203.221083] synchronize_sched()
> in 41 us
> May  8 09:47:57 nattytest kernel: [  203.222692] synchronize_sched()
> in 68 us
> May  8 09:47:58 nattytest kernel: [  203.350083] synchronize_sched()
> in 74062 us
> May  8 09:47:58 nattytest kernel: [  203.430100] synchronize_sched()
> in 78468 us
> May  8 09:47:58 nattytest kernel: [  203.491028] synchronize_sched()
> in 52 us
> May  8 09:47:58 nattytest kernel: [  203.510086] synchronize_sched()
> in 17607 us
> May  8 09:47:58 nattytest kernel: [  203.670080] synchronize_sched()
> in 83798 us
> May  8 09:47:58 nattytest kernel: [  203.750080] synchronize_sched()
> in 78382 us
> May  8 09:47:58 nattytest kernel: [  203.821032] synchronize_sched()
> in 48 us
> May  8 09:47:58 nattytest kernel: [  203.840093] synchronize_sched()
> in 17608 us
> May  8 09:47:58 nattytest kernel: [  203.990084] synchronize_sched()
> in 73664 us
> May  8 09:47:58 nattytest kernel: [  204.080078] synchronize_sched()
> in 88391 us
> May  8 09:47:58 nattytest kernel: [  204.141021] synchronize_sched()
> in 44 us
> May  8 09:47:58 nattytest kernel: [  204.160083] synchronize_sched()
> in 17671 us
> May  8 09:47:59 nattytest kernel: [  204.310086] synchronize_sched()
> in 83288 us
> May  8 09:47:59 nattytest kernel: [  204.380074] synchronize_sched()
> in 69168 us
> May  8 09:47:59 nattytest kernel: [  204.431059] synchronize_sched()
> in 67 us
> May  8 09:47:59 nattytest kernel: [  204.432205] synchronize_sched()
> in 30 us
> May  8 09:47:59 nattytest kernel: [  204.550147] synchronize_sched()
> in 54218 us
> May  8 09:47:59 nattytest kernel: [  204.640079] synchronize_sched()
> in 88401 us
> May  8 09:47:59 nattytest kernel: [  204.701062] synchronize_sched()
> in 48 us
> May  8 09:47:59 nattytest kernel: [  204.720093] synchronize_sched()
> in 17508 us
> May  8 09:47:59 nattytest kernel: [  204.850108] synchronize_sched()
> in 73968 us
> May  8 09:47:59 nattytest kernel: [  204.940074] synchronize_sched()
> in 88489 us
> May  8 09:47:59 nattytest kernel: [  205.011002] synchronize_sched()
> in 44 us
> May  8 09:47:59 nattytest kernel: [  205.030104] synchronize_sched()
> in 17658 us
> May  8 09:47:59 nattytest kernel: [  205.190091] synchronize_sched()
> in 83651 us
> May  8 09:48:00 nattytest kernel: [  205.270094] synchronize_sched()
> in 78501 us
> May  8 09:48:00 nattytest kernel: [  205.341000] synchronize_sched()
> in 65 us
> May  8 09:48:00 nattytest kernel: [  205.360081] synchronize_sched()
> in 17640 us
> 
> 
> 
>