Re: Strange issue after early AP startup

On 01/17/17 16:50, John Baldwin wrote:
 > On Monday, January 16, 2017 10:10:16 PM Hans Petter Selasky wrote:
 >> On 01/16/17 20:31, John Baldwin wrote:
 >>> On Monday, January 16, 2017 04:51:42 PM Hans Petter Selasky wrote:
 >>>> Hi,
 >>>>
 >>>> When booting I observe an additional 30-second delay after this print:
 >>>>
 >>>>> Timecounters tick every 1.000 msec
 >>>>
 >>>> ~30 second delay and boot continues like normal.
 >>>>
 >>>> Checking "vmstat -i" reveals that some timers have been running loose.
 >>>>
 >>>>> cpu0:timer                         44300        442
 >>>>> cpu1:timer                         40561        404
 >>>>> cpu3:timer                      48462822     483058
 >>>>> cpu2:timer                      48477898     483209
 >>>>
 >>>> Trying to add delays and/or prints around the Timecounters printout
 >>>> makes the issue go away. Any ideas for debugging?
 >>>
 >>> I have generally used KTR tracing to trace what is happening during
 >>> boot to debug EARLY_AP_STARTUP issues.
 >>>
 >>
 >> Hi John,
 >>
 >> What happens is that getnextcpuevent(0) keeps on returning
 >> "state->nextcall" which is in the past for CPU #2 and #3 on my box.
 >>
 >> In "cpu_new_callout()" there is a check if "bt >= state->nextcall",
 >> which I suspect is true, so "state->nextcall" never gets set to real
 >> minimum sbintime.
 >>
 >> The attached patch fixes the problem for me, but I'm not 100% sure 
if it
 >> is correct.
 >

Hi,

 > I think we want to be honoring any currently scheduled callouts.

The problem here is that we might be changing the clocksource, then 
sbinuptime() will change too, so I think the value should be reset by 
configtimer() and then corrected at the next call to callout_process().

 > You could
 > do that by setting it to 'cc_firstevent' of the associated CPU, but in
 > practice 'state->nextcall' should already be set to that (it is 
initalized
 > to SBT_MAX in cpu_initclocks_bsp() and is then only set to other 
values due
 > to cpu_new_callout()).  Keep in mind that configtimer() is not just 
called
 > from boot, but is also invoked when starting/stopping the profiling 
timer.
 >

 > However, when setting 'nextevent' (which is used to schedule the next 
timer
 > interrupt), we should be honoring the existing 'nextcall' if it is sooner
 > than the next hardclock.

Does this matter for the first tick? How often is configtimer() called?

 > (One odd thing is that even in your case the first call to 
handleevents(),
 > the 'now => state->nextcallout' check in handleevents() should be true
 > which resets both nextcall and nextcallopt and invokes 
callout_process().)

Let me take you through the failure path, by code inspection:

1) configtimer() is called and we init nextcall and nextcallopt:

 >                 next = now + timerperiod;
...
 >                       state->nextcall = next;
 >                       state->nextcallopt = next;

2) Any callout_reset() calls cpu_new_callout():

 >          */
 >         state->nextcallopt = bt_opt;
 >         if (bt >= state->nextcall)
We follow this path, because "bt" is surely based on sbinuptime() and is 
greater or equal to state->nextcall. Note that state->nextcallopt is 
updated to bt_opt, which is in the future.
 >                 goto done;
 >         state->nextcall = bt;

3) getnextcpuevent(0) is called by the fast timercb() to setup the next 
event:

 >         state = DPCPU_PTR(timerstate);
 >         /* Handle hardclock() events, skipping some if CPU is idle. */
 >         event = state->nexthard;
...
 >         /* Handle callout events. */
 >         if (event > state->nextcall)
We then go looping into this path, because state->nextcall is still 
equal to "next" as in step 1) which is now in the past, until "now >= 
state->nextcallopt" inside handleevents(), which clears this condition.
 >                 event = state->nextcall;
...
 >         return (event);

--HPS