Re: When is a wake_up() not a wake up?

[Andy Walls]

On Sat, 2009-04-04 at 04:07 -0700, Trent Piepho wrote:
 On Fri, 3 Apr 2009, Andy Walls wrote:
  1. A work queue thread or read() call needs to send a command to the
  CX23418 using the cx18_api_call() function
  2. It fills out a mailbox with a command for the CX23418
  3. It prepares to wait, just in case a wait is needed
  4. A SW1 interrupt is sent to the CX23418 telling it a mailbox is ready
  5. The ack filed in the mailbox, a PCI MMIO location, is checked to see
  if the mailbox was ack'ed already
  6. If not, schedule_timeout() for up to 10 msecs (a near eternity...)
  7. Clean up the wait and move on
 
 10ms isn't that long.  With a 100 HZ kernel it's only one jiffie.  The
 shortest time msleep() can sleep on a 100 HZ kernel is 20 ms.
 
 Is it possible that it's simply taking more than 10 ms for your process to
 get run?

After some testing with fine grained timestamps as you suggested, that
indeed appears to be the case.

For the high volume API command I care about, in 6097 out of 6100
samples, the firmware acknowledgment interrupt comes back in and the
process is awakened back to TASK_RUNNABLE in under 150 us.  0 out of
6100 samples finished the wakeup to TASK_RUNNABLE faster than 55 us.
However, I had 22 samples, where coming back from schedule_timeout()
took 10 msec or greater, despite the wakeup happening in under 150 us.

So the simple answer is to poll the ack field of the mailbox, with some
50 us busy waits perhaps, for this one high volume API command.

Regards,
Andy

--
To unsubscribe from this list: send the line unsubscribe linux-media in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: When is a wake_up() not a wake up?

[Trent Piepho]

On Fri, 3 Apr 2009, Andy Walls wrote:
 1. A work queue thread or read() call needs to send a command to the
 CX23418 using the cx18_api_call() function
 2. It fills out a mailbox with a command for the CX23418
 3. It prepares to wait, just in case a wait is needed
 4. A SW1 interrupt is sent to the CX23418 telling it a mailbox is ready
 5. The ack filed in the mailbox, a PCI MMIO location, is checked to see
 if the mailbox was ack'ed already
 6. If not, schedule_timeout() for up to 10 msecs (a near eternity...)
 7. Clean up the wait and move on

10ms isn't that long.  With a 100 HZ kernel it's only one jiffie.  The
shortest time msleep() can sleep on a 100 HZ kernel is 20 ms.

Is it possible that it's simply taking more than 10 ms for your process to
get run?

 Mar 31 23:36:56 palomino kernel: cx18-0:  irq: sending interrupt SW1: 8 to 
 send CX18_CPU_DE_SET_MDL
 Mar 31 23:36:56 palomino kernel: cx18-0:  api: scheduling to wait for ack of 
 CX18_CPU_DE_SET_MDL: req 51267 ack 51266, pid 21092, state 2
 Mar 31 23:36:56 palomino kernel: cx18-0:  irq: received interrupts SW1: 0  
 SW2: 8  HW2: 0
 Mar 31 23:36:56 palomino kernel: cx18-0:  irq: Wake up initiated on pid 21092 
 in state 2
 Mar 31 23:36:56 palomino kernel: cx18-0:  irq: Wake up succeeded on pid 
 21092, state 2 - 0
 Mar 31 23:36:56 palomino kernel: cx18-0:  api: done wait for ack of 
 CX18_CPU_DE_SET_MDL: req 51267 ack 51267, current pid 21092, current state 0, 
 state 0
 Mar 31 23:36:56 palomino kernel: cx18-0:  warning: failed to be awakened upon 
 RPU acknowledgment sending CX18_CPU_DE_SET_MDL; timed out waiting 10 msecs

Try some higher resolution time stamps, you can't really tell much about
when things are happening.

Here's some code I wrote to do it on x86.

#include linux/calc64.h
#define MHZ 1666.787
#define INT (unsigned int)(MHZ * (112) + 0.5)
#define FRAC(unsigned int)(MHZ * (121) / 1000.0 + 0.5)
#define timestamp(str, args...) { u64 _time; u32 _rem; rdtscll(_time); \
_time = (_time - starttime)12; \
_rem = do_div(_time, INT); \
printk(%s - %u.%03u us  str \n, __func__, \
(unsigned int)_time, (_rem  9) / FRAC , ## args); }
static u64 starttime;

Change MHZ to what /proc/cpuinfo tells you.  Call 'rdtscll(starttime)' some
time when your driver inits or a device gets opened or something like that.
Makes the time stamps easier to read when they start near zero.
--
To unsubscribe from this list: send the line unsubscribe linux-media in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html