* doubt on schedule_work() - work task getting scheduled lately
@ 2016-07-29 10:32 Muni Sekhar
2016-07-29 10:44 ` Pranay Srivastava
2016-08-05 5:44 ` Mulyadi Santosa
0 siblings, 2 replies; 10+ messages in thread
From: Muni Sekhar @ 2016-07-29 10:32 UTC (permalink / raw)
To: kernelnewbies
Hi All,
I have a doubt regarding the workqueue scheduling.
I am using the workqueue for processing the Rx Interrupt data. I am
calling schedule_work() on receiving the Rx interrupt from hardware.
I calculated the time between calling the schedule_work() and
workqueue task actually getting executed, Here I see many cases of
less than 100 us(It is fairly good).
But sometimes I see 10?s of ms and a lot in the 100?s of ms. I have
seen over 0.5 secs too. I would like to know why does sometimes kernel
takes longer time(in milli seconds) to schedule it? Is there any way
to reduce this time gap?
My code:
static void my_workqueuetask(struct work_struct *work)
{
printk("In %s() \n",__func__);
mutex_lock(&bh_mutex);
//Do something here
mutex_unlock(&bh_mutex);
}
static irqreturn_t my_irq_handler(int irq, void *dev)
{
??;
if(Rx Interrupt)
schedule_work(&rx_work);
return IRQ_HANDLED;
}
--
Thanks,
Sekhar
^ permalink raw reply [flat|nested] 10+ messages in thread* doubt on schedule_work() - work task getting scheduled lately 2016-07-29 10:32 doubt on schedule_work() - work task getting scheduled lately Muni Sekhar @ 2016-07-29 10:44 ` Pranay Srivastava 2016-07-29 13:48 ` Ricardo Ribalda Delgado 2016-08-05 5:44 ` Mulyadi Santosa 1 sibling, 1 reply; 10+ messages in thread From: Pranay Srivastava @ 2016-07-29 10:44 UTC (permalink / raw) To: kernelnewbies On Fri, Jul 29, 2016 at 4:02 PM, Muni Sekhar <munisekharrms@gmail.com> wrote: > Hi All, > > I have a doubt regarding the workqueue scheduling. > > I am using the workqueue for processing the Rx Interrupt data. I am > calling schedule_work() on receiving the Rx interrupt from hardware. > > I calculated the time between calling the schedule_work() and > workqueue task actually getting executed, Here I see many cases of > less than 100 us(It is fairly good). > > But sometimes I see 10?s of ms and a lot in the 100?s of ms. I have > seen over 0.5 secs too. I would like to know why does sometimes kernel > takes longer time(in milli seconds) to schedule it? Is there any way > to reduce this time gap? > > > My code: > > static void my_workqueuetask(struct work_struct *work) > { > printk("In %s() \n",__func__); > You probably don't need this if it's just for your work_fn, yeah but if there's race between this and something else... > mutex_lock(&bh_mutex); > > //Do something here > > mutex_unlock(&bh_mutex); > } > > > static irqreturn_t my_irq_handler(int irq, void *dev) > { > ??; > > if(Rx Interrupt) > schedule_work(&rx_work); Maybe system_wq has too much already on it's plate? Have you tried the same with completion and a kthread? or with your own workqueue, overkill but you can give it a shot. > > return IRQ_HANDLED; > } > > -- > Thanks, > Sekhar > > _______________________________________________ > Kernelnewbies mailing list > Kernelnewbies at kernelnewbies.org > https://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies -- ---P.K.S ^ permalink raw reply [flat|nested] 10+ messages in thread
* doubt on schedule_work() - work task getting scheduled lately 2016-07-29 10:44 ` Pranay Srivastava @ 2016-07-29 13:48 ` Ricardo Ribalda Delgado 2016-07-29 15:35 ` Daniel. 0 siblings, 1 reply; 10+ messages in thread From: Ricardo Ribalda Delgado @ 2016-07-29 13:48 UTC (permalink / raw) To: kernelnewbies you can use http://lttng.org/ for analyzing this Regards! On Fri, Jul 29, 2016 at 12:44 PM, Pranay Srivastava <pranjas@gmail.com> wrote: > On Fri, Jul 29, 2016 at 4:02 PM, Muni Sekhar <munisekharrms@gmail.com> wrote: >> Hi All, >> >> I have a doubt regarding the workqueue scheduling. >> >> I am using the workqueue for processing the Rx Interrupt data. I am >> calling schedule_work() on receiving the Rx interrupt from hardware. >> >> I calculated the time between calling the schedule_work() and >> workqueue task actually getting executed, Here I see many cases of >> less than 100 us(It is fairly good). >> >> But sometimes I see 10?s of ms and a lot in the 100?s of ms. I have >> seen over 0.5 secs too. I would like to know why does sometimes kernel >> takes longer time(in milli seconds) to schedule it? Is there any way >> to reduce this time gap? >> >> >> My code: >> >> static void my_workqueuetask(struct work_struct *work) >> { >> printk("In %s() \n",__func__); >> > You probably don't need this if it's just for your work_fn, yeah but > if there's race between this and something else... >> mutex_lock(&bh_mutex); >> >> //Do something here >> >> mutex_unlock(&bh_mutex); >> } >> >> >> static irqreturn_t my_irq_handler(int irq, void *dev) >> { >> ??; >> >> if(Rx Interrupt) >> schedule_work(&rx_work); > > Maybe system_wq has too much already on it's plate? > Have you tried the same with completion and a kthread? or > with your own workqueue, overkill but you can give it a shot. >> >> return IRQ_HANDLED; >> } >> >> -- >> Thanks, >> Sekhar >> >> _______________________________________________ >> Kernelnewbies mailing list >> Kernelnewbies at kernelnewbies.org >> https://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies > > > > -- > ---P.K.S > > _______________________________________________ > Kernelnewbies mailing list > Kernelnewbies at kernelnewbies.org > https://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies -- Ricardo Ribalda ^ permalink raw reply [flat|nested] 10+ messages in thread
* doubt on schedule_work() - work task getting scheduled lately 2016-07-29 13:48 ` Ricardo Ribalda Delgado @ 2016-07-29 15:35 ` Daniel. 2016-08-01 10:32 ` Muni Sekhar 0 siblings, 1 reply; 10+ messages in thread From: Daniel. @ 2016-07-29 15:35 UTC (permalink / raw) To: kernelnewbies Nice tool @Ricardo! 2016-07-29 10:48 GMT-03:00 Ricardo Ribalda Delgado <ricardo.ribalda@gmail.com>: > you can use http://lttng.org/ for analyzing this > > Regards! > > On Fri, Jul 29, 2016 at 12:44 PM, Pranay Srivastava <pranjas@gmail.com> wrote: >> On Fri, Jul 29, 2016 at 4:02 PM, Muni Sekhar <munisekharrms@gmail.com> wrote: >>> Hi All, >>> >>> I have a doubt regarding the workqueue scheduling. >>> >>> I am using the workqueue for processing the Rx Interrupt data. I am >>> calling schedule_work() on receiving the Rx interrupt from hardware. >>> >>> I calculated the time between calling the schedule_work() and >>> workqueue task actually getting executed, Here I see many cases of >>> less than 100 us(It is fairly good). >>> >>> But sometimes I see 10?s of ms and a lot in the 100?s of ms. I have >>> seen over 0.5 secs too. I would like to know why does sometimes kernel >>> takes longer time(in milli seconds) to schedule it? Is there any way >>> to reduce this time gap? >>> >>> >>> My code: >>> >>> static void my_workqueuetask(struct work_struct *work) >>> { >>> printk("In %s() \n",__func__); >>> >> You probably don't need this if it's just for your work_fn, yeah but >> if there's race between this and something else... >>> mutex_lock(&bh_mutex); >>> >>> //Do something here >>> >>> mutex_unlock(&bh_mutex); >>> } >>> >>> >>> static irqreturn_t my_irq_handler(int irq, void *dev) >>> { >>> ??; >>> >>> if(Rx Interrupt) >>> schedule_work(&rx_work); >> >> Maybe system_wq has too much already on it's plate? >> Have you tried the same with completion and a kthread? or >> with your own workqueue, overkill but you can give it a shot. >>> >>> return IRQ_HANDLED; >>> } >>> >>> -- >>> Thanks, >>> Sekhar >>> >>> _______________________________________________ >>> Kernelnewbies mailing list >>> Kernelnewbies at kernelnewbies.org >>> https://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies >> >> >> >> -- >> ---P.K.S >> >> _______________________________________________ >> Kernelnewbies mailing list >> Kernelnewbies at kernelnewbies.org >> https://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies > > > > -- > Ricardo Ribalda > > _______________________________________________ > Kernelnewbies mailing list > Kernelnewbies at kernelnewbies.org > https://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies -- "Do or do not. There is no try" Yoda Master ^ permalink raw reply [flat|nested] 10+ messages in thread
* doubt on schedule_work() - work task getting scheduled lately 2016-07-29 15:35 ` Daniel. @ 2016-08-01 10:32 ` Muni Sekhar 2016-08-01 13:04 ` Daniel. 0 siblings, 1 reply; 10+ messages in thread From: Muni Sekhar @ 2016-08-01 10:32 UTC (permalink / raw) To: kernelnewbies On Fri, Jul 29, 2016 at 9:05 PM, Daniel. <danielhilst@gmail.com> wrote: > Nice tool @Ricardo! > > 2016-07-29 10:48 GMT-03:00 Ricardo Ribalda Delgado <ricardo.ribalda@gmail.com>: >> you can use http://lttng.org/ for analyzing this Thanks Ricardo, I will use this. >> >> Regards! >> >> On Fri, Jul 29, 2016 at 12:44 PM, Pranay Srivastava <pranjas@gmail.com> wrote: >>> On Fri, Jul 29, 2016 at 4:02 PM, Muni Sekhar <munisekharrms@gmail.com> wrote: >>>> Hi All, >>>> >>>> I have a doubt regarding the workqueue scheduling. >>>> >>>> I am using the workqueue for processing the Rx Interrupt data. I am >>>> calling schedule_work() on receiving the Rx interrupt from hardware. >>>> >>>> I calculated the time between calling the schedule_work() and >>>> workqueue task actually getting executed, Here I see many cases of >>>> less than 100 us(It is fairly good). >>>> >>>> But sometimes I see 10?s of ms and a lot in the 100?s of ms. I have >>>> seen over 0.5 secs too. I would like to know why does sometimes kernel >>>> takes longer time(in milli seconds) to schedule it? Is there any way >>>> to reduce this time gap? >>>> >>>> >>>> My code: >>>> >>>> static void my_workqueuetask(struct work_struct *work) >>>> { >>>> printk("In %s() \n",__func__); >>>> >>> You probably don't need this if it's just for your work_fn, yeah but >>> if there's race between this and something else... >>>> mutex_lock(&bh_mutex); >>>> >>>> //Do something here >>>> >>>> mutex_unlock(&bh_mutex); >>>> } >>>> >>>> >>>> static irqreturn_t my_irq_handler(int irq, void *dev) >>>> { >>>> ??; >>>> >>>> if(Rx Interrupt) >>>> schedule_work(&rx_work); >>> >>> Maybe system_wq has too much already on it's plate? >>> Have you tried the same with completion and a kthread? or >>> with your own workqueue, overkill but you can give it a shot. I have not tried this. First I will analyze with lttng and then attempts this. Does using our own workqueue reduces the latency? >>>> >>>> return IRQ_HANDLED; >>>> } >>>> >>>> -- >>>> Thanks, >>>> Sekhar >>>> >>>> _______________________________________________ >>>> Kernelnewbies mailing list >>>> Kernelnewbies at kernelnewbies.org >>>> https://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies >>> >>> >>> >>> -- >>> ---P.K.S >>> >>> _______________________________________________ >>> Kernelnewbies mailing list >>> Kernelnewbies at kernelnewbies.org >>> https://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies >> >> >> >> -- >> Ricardo Ribalda >> >> _______________________________________________ >> Kernelnewbies mailing list >> Kernelnewbies at kernelnewbies.org >> https://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies > > > > -- > "Do or do not. There is no try" > Yoda Master > > _______________________________________________ > Kernelnewbies mailing list > Kernelnewbies at kernelnewbies.org > https://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies -- Thanks, Sekhar ^ permalink raw reply [flat|nested] 10+ messages in thread
* doubt on schedule_work() - work task getting scheduled lately 2016-08-01 10:32 ` Muni Sekhar @ 2016-08-01 13:04 ` Daniel. 2016-08-05 7:22 ` Muni Sekhar 0 siblings, 1 reply; 10+ messages in thread From: Daniel. @ 2016-08-01 13:04 UTC (permalink / raw) To: kernelnewbies Did you tried ftrace? https://www.kernel.org/doc/Documentation/trace/ftrace.txt I've been using this to measure some latencies. The problem here is visualizing the output. If you need someting more elaborated than simple prints with timestamps and delta calculations, then you should try something more complex. If not you can enable FTRACE and generate trace output with delta timestamps on it, event for interrupts :) Best regards, 2016-08-01 7:32 GMT-03:00 Muni Sekhar <munisekharrms@gmail.com>: > On Fri, Jul 29, 2016 at 9:05 PM, Daniel. <danielhilst@gmail.com> wrote: >> Nice tool @Ricardo! >> >> 2016-07-29 10:48 GMT-03:00 Ricardo Ribalda Delgado <ricardo.ribalda@gmail.com>: >>> you can use http://lttng.org/ for analyzing this > Thanks Ricardo, I will use this. > >>> >>> Regards! >>> >>> On Fri, Jul 29, 2016 at 12:44 PM, Pranay Srivastava <pranjas@gmail.com> wrote: >>>> On Fri, Jul 29, 2016 at 4:02 PM, Muni Sekhar <munisekharrms@gmail.com> wrote: >>>>> Hi All, >>>>> >>>>> I have a doubt regarding the workqueue scheduling. >>>>> >>>>> I am using the workqueue for processing the Rx Interrupt data. I am >>>>> calling schedule_work() on receiving the Rx interrupt from hardware. >>>>> >>>>> I calculated the time between calling the schedule_work() and >>>>> workqueue task actually getting executed, Here I see many cases of >>>>> less than 100 us(It is fairly good). >>>>> >>>>> But sometimes I see 10?s of ms and a lot in the 100?s of ms. I have >>>>> seen over 0.5 secs too. I would like to know why does sometimes kernel >>>>> takes longer time(in milli seconds) to schedule it? Is there any way >>>>> to reduce this time gap? >>>>> >>>>> >>>>> My code: >>>>> >>>>> static void my_workqueuetask(struct work_struct *work) >>>>> { >>>>> printk("In %s() \n",__func__); >>>>> >>>> You probably don't need this if it's just for your work_fn, yeah but >>>> if there's race between this and something else... >>>>> mutex_lock(&bh_mutex); >>>>> >>>>> //Do something here >>>>> >>>>> mutex_unlock(&bh_mutex); >>>>> } >>>>> >>>>> >>>>> static irqreturn_t my_irq_handler(int irq, void *dev) >>>>> { >>>>> ??; >>>>> >>>>> if(Rx Interrupt) >>>>> schedule_work(&rx_work); >>>> >>>> Maybe system_wq has too much already on it's plate? >>>> Have you tried the same with completion and a kthread? or >>>> with your own workqueue, overkill but you can give it a shot. > I have not tried this. First I will analyze with lttng and then > attempts this. Does using our own workqueue reduces the latency? > >>>>> >>>>> return IRQ_HANDLED; >>>>> } >>>>> >>>>> -- >>>>> Thanks, >>>>> Sekhar >>>>> >>>>> _______________________________________________ >>>>> Kernelnewbies mailing list >>>>> Kernelnewbies at kernelnewbies.org >>>>> https://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies >>>> >>>> >>>> >>>> -- >>>> ---P.K.S >>>> >>>> _______________________________________________ >>>> Kernelnewbies mailing list >>>> Kernelnewbies at kernelnewbies.org >>>> https://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies >>> >>> >>> >>> -- >>> Ricardo Ribalda >>> >>> _______________________________________________ >>> Kernelnewbies mailing list >>> Kernelnewbies at kernelnewbies.org >>> https://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies >> >> >> >> -- >> "Do or do not. There is no try" >> Yoda Master >> >> _______________________________________________ >> Kernelnewbies mailing list >> Kernelnewbies at kernelnewbies.org >> https://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies > > > > -- > Thanks, > Sekhar -- "Do or do not. There is no try" Yoda Master ^ permalink raw reply [flat|nested] 10+ messages in thread
* doubt on schedule_work() - work task getting scheduled lately 2016-08-01 13:04 ` Daniel. @ 2016-08-05 7:22 ` Muni Sekhar 2016-08-05 13:09 ` Daniel. 0 siblings, 1 reply; 10+ messages in thread From: Muni Sekhar @ 2016-08-05 7:22 UTC (permalink / raw) To: kernelnewbies On Mon, Aug 1, 2016 at 6:34 PM, Daniel. <danielhilst@gmail.com> wrote: > Did you tried ftrace? https://www.kernel.org/doc/Documentation/trace/ftrace.txt > > I've been using this to measure some latencies. The problem here is > visualizing the output. If you need someting more elaborated than > simple prints with timestamps and delta calculations, then you should > try something more complex. If not you can enable FTRACE and generate > trace output with delta timestamps on it, event for interrupts :) No, I haven't tried ftrace. I need to measure latencies between schedule_work() and actual execution start of my work function. workqueue_queue_work & workqueue_execute_start are their corresponding lttng events. I installed the lttng in my test setup and simply enabled all available kernel events. I am able to start & stop tracing. Few lines of lttng view trace: [11:07:08.208795325] (+0.000001677) testbox irq_handler_entry: { cpu_id = 1 }, { irq = 16, name = "debug_irq" } [11:07:08.208822703] (+0.000027378) testbox workqueue_queue_work: { cpu_id = 1 }, { work = 0xFFFF8801396D4F18, function = 0xFFFFFFFFC07273B0, req_cpu = 256 } [11:07:08.208824380] (+0.000001677) testbox workqueue_activate_work: { cpu_id = 1 }, { work = 0xFFFF8801396D4F18 } [11:07:08.208826615] (+0.000002235) testbox irq_handler_exit: { cpu_id = 1 }, { irq = 16, ret = 1 } [11:07:08.208831364] (+0.000004749) testbox workqueue_execute_start: { cpu_id = 1 }, { work = 0xFFFF8801396D4F18, function = 0xFFFFFFFFC07273B0 } [11:07:08.208841422] (+0.000010058) testbox workqueue_execute_end: { cpu_id = 1 }, { work = 0xFFFF8801396D4F18 } Can it be possible to print function name instead of ?function = 0xFFFFFFFFC07273B0?? Reproducing the 100 msec latency in between workqueue_queue_work & workqueue_execute_start needs to trigger the longer soak test anything over 24 hours. If I record the lttng trace for longer hours and when I 'lttng view' the trace, I get all sorts of messages like: "[warning] Tracer discarded XXXX events between <timestamp1> and <timestamp2>. You should consider recording a new trace with larger buffers or with fewer events enabled." Any better ideas to catch the kernel trace event log for millisecond latency in between workqueue_queue_work & workqueue_execute_start? > > Best regards, > > 2016-08-01 7:32 GMT-03:00 Muni Sekhar <munisekharrms@gmail.com>: >> On Fri, Jul 29, 2016 at 9:05 PM, Daniel. <danielhilst@gmail.com> wrote: >>> Nice tool @Ricardo! >>> >>> 2016-07-29 10:48 GMT-03:00 Ricardo Ribalda Delgado <ricardo.ribalda@gmail.com>: >>>> you can use http://lttng.org/ for analyzing this >> Thanks Ricardo, I will use this. >> >>>> >>>> Regards! >>>> >>>> On Fri, Jul 29, 2016 at 12:44 PM, Pranay Srivastava <pranjas@gmail.com> wrote: >>>>> On Fri, Jul 29, 2016 at 4:02 PM, Muni Sekhar <munisekharrms@gmail.com> wrote: >>>>>> Hi All, >>>>>> >>>>>> I have a doubt regarding the workqueue scheduling. >>>>>> >>>>>> I am using the workqueue for processing the Rx Interrupt data. I am >>>>>> calling schedule_work() on receiving the Rx interrupt from hardware. >>>>>> >>>>>> I calculated the time between calling the schedule_work() and >>>>>> workqueue task actually getting executed, Here I see many cases of >>>>>> less than 100 us(It is fairly good). >>>>>> >>>>>> But sometimes I see 10?s of ms and a lot in the 100?s of ms. I have >>>>>> seen over 0.5 secs too. I would like to know why does sometimes kernel >>>>>> takes longer time(in milli seconds) to schedule it? Is there any way >>>>>> to reduce this time gap? >>>>>> >>>>>> >>>>>> My code: >>>>>> >>>>>> static void my_workqueuetask(struct work_struct *work) >>>>>> { >>>>>> printk("In %s() \n",__func__); >>>>>> >>>>> You probably don't need this if it's just for your work_fn, yeah but >>>>> if there's race between this and something else... >>>>>> mutex_lock(&bh_mutex); >>>>>> >>>>>> //Do something here >>>>>> >>>>>> mutex_unlock(&bh_mutex); >>>>>> } >>>>>> >>>>>> >>>>>> static irqreturn_t my_irq_handler(int irq, void *dev) >>>>>> { >>>>>> ??; >>>>>> >>>>>> if(Rx Interrupt) >>>>>> schedule_work(&rx_work); >>>>> >>>>> Maybe system_wq has too much already on it's plate? >>>>> Have you tried the same with completion and a kthread? or >>>>> with your own workqueue, overkill but you can give it a shot. >> I have not tried this. First I will analyze with lttng and then >> attempts this. Does using our own workqueue reduces the latency? >> >>>>>> >>>>>> return IRQ_HANDLED; >>>>>> } >>>>>> >>>>>> -- >>>>>> Thanks, >>>>>> Sekhar >>>>>> >>>>>> _______________________________________________ >>>>>> Kernelnewbies mailing list >>>>>> Kernelnewbies at kernelnewbies.org >>>>>> https://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies >>>>> >>>>> >>>>> >>>>> -- >>>>> ---P.K.S >>>>> >>>>> _______________________________________________ >>>>> Kernelnewbies mailing list >>>>> Kernelnewbies at kernelnewbies.org >>>>> https://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies >>>> >>>> >>>> >>>> -- >>>> Ricardo Ribalda >>>> >>>> _______________________________________________ >>>> Kernelnewbies mailing list >>>> Kernelnewbies at kernelnewbies.org >>>> https://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies >>> >>> >>> >>> -- >>> "Do or do not. There is no try" >>> Yoda Master >>> >>> _______________________________________________ >>> Kernelnewbies mailing list >>> Kernelnewbies at kernelnewbies.org >>> https://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies >> >> >> >> -- >> Thanks, >> Sekhar > > > > -- > "Do or do not. There is no try" > Yoda Master -- Thanks, Sekhar ^ permalink raw reply [flat|nested] 10+ messages in thread
* doubt on schedule_work() - work task getting scheduled lately 2016-08-05 7:22 ` Muni Sekhar @ 2016-08-05 13:09 ` Daniel. 0 siblings, 0 replies; 10+ messages in thread From: Daniel. @ 2016-08-05 13:09 UTC (permalink / raw) To: kernelnewbies ftrace :) 2016-08-05 4:22 GMT-03:00 Muni Sekhar <munisekharrms@gmail.com>: > On Mon, Aug 1, 2016 at 6:34 PM, Daniel. <danielhilst@gmail.com> wrote: >> Did you tried ftrace? https://www.kernel.org/doc/Documentation/trace/ftrace.txt >> >> I've been using this to measure some latencies. The problem here is >> visualizing the output. If you need someting more elaborated than >> simple prints with timestamps and delta calculations, then you should >> try something more complex. If not you can enable FTRACE and generate >> trace output with delta timestamps on it, event for interrupts :) > > No, I haven't tried ftrace. > > > I need to measure latencies between schedule_work() and actual > execution start of my work function. workqueue_queue_work & > workqueue_execute_start are their corresponding lttng events. > > I installed the lttng in my test setup and simply enabled all > available kernel events. > > I am able to start & stop tracing. > > > Few lines of lttng view trace: > > [11:07:08.208795325] (+0.000001677) testbox irq_handler_entry: { > cpu_id = 1 }, { irq = 16, name = "debug_irq" } > > [11:07:08.208822703] (+0.000027378) testbox workqueue_queue_work: { > cpu_id = 1 }, { work = 0xFFFF8801396D4F18, function = > 0xFFFFFFFFC07273B0, req_cpu = 256 } > > [11:07:08.208824380] (+0.000001677) testbox workqueue_activate_work: { > cpu_id = 1 }, { work = 0xFFFF8801396D4F18 } > > [11:07:08.208826615] (+0.000002235) testbox irq_handler_exit: { cpu_id > = 1 }, { irq = 16, ret = 1 } > > [11:07:08.208831364] (+0.000004749) testbox workqueue_execute_start: { > cpu_id = 1 }, { work = 0xFFFF8801396D4F18, function = > 0xFFFFFFFFC07273B0 } > > [11:07:08.208841422] (+0.000010058) testbox workqueue_execute_end: { > cpu_id = 1 }, { work = 0xFFFF8801396D4F18 } > > > Can it be possible to print function name instead of ?function = > 0xFFFFFFFFC07273B0?? > > > > Reproducing the 100 msec latency in between workqueue_queue_work & > workqueue_execute_start needs to trigger the longer soak test anything > over 24 hours. > > > If I record the lttng trace for longer hours and when I 'lttng view' > the trace, I get all sorts of messages like: > > > "[warning] Tracer discarded XXXX events between <timestamp1> and > <timestamp2>. You should consider recording a new trace with larger > buffers or with fewer events enabled." > > > Any better ideas to catch the kernel trace event log for millisecond > latency in between workqueue_queue_work & workqueue_execute_start? > > > >> >> Best regards, >> >> 2016-08-01 7:32 GMT-03:00 Muni Sekhar <munisekharrms@gmail.com>: >>> On Fri, Jul 29, 2016 at 9:05 PM, Daniel. <danielhilst@gmail.com> wrote: >>>> Nice tool @Ricardo! >>>> >>>> 2016-07-29 10:48 GMT-03:00 Ricardo Ribalda Delgado <ricardo.ribalda@gmail.com>: >>>>> you can use http://lttng.org/ for analyzing this >>> Thanks Ricardo, I will use this. >>> >>>>> >>>>> Regards! >>>>> >>>>> On Fri, Jul 29, 2016 at 12:44 PM, Pranay Srivastava <pranjas@gmail.com> wrote: >>>>>> On Fri, Jul 29, 2016 at 4:02 PM, Muni Sekhar <munisekharrms@gmail.com> wrote: >>>>>>> Hi All, >>>>>>> >>>>>>> I have a doubt regarding the workqueue scheduling. >>>>>>> >>>>>>> I am using the workqueue for processing the Rx Interrupt data. I am >>>>>>> calling schedule_work() on receiving the Rx interrupt from hardware. >>>>>>> >>>>>>> I calculated the time between calling the schedule_work() and >>>>>>> workqueue task actually getting executed, Here I see many cases of >>>>>>> less than 100 us(It is fairly good). >>>>>>> >>>>>>> But sometimes I see 10?s of ms and a lot in the 100?s of ms. I have >>>>>>> seen over 0.5 secs too. I would like to know why does sometimes kernel >>>>>>> takes longer time(in milli seconds) to schedule it? Is there any way >>>>>>> to reduce this time gap? >>>>>>> >>>>>>> >>>>>>> My code: >>>>>>> >>>>>>> static void my_workqueuetask(struct work_struct *work) >>>>>>> { >>>>>>> printk("In %s() \n",__func__); >>>>>>> >>>>>> You probably don't need this if it's just for your work_fn, yeah but >>>>>> if there's race between this and something else... >>>>>>> mutex_lock(&bh_mutex); >>>>>>> >>>>>>> //Do something here >>>>>>> >>>>>>> mutex_unlock(&bh_mutex); >>>>>>> } >>>>>>> >>>>>>> >>>>>>> static irqreturn_t my_irq_handler(int irq, void *dev) >>>>>>> { >>>>>>> ??; >>>>>>> >>>>>>> if(Rx Interrupt) >>>>>>> schedule_work(&rx_work); >>>>>> >>>>>> Maybe system_wq has too much already on it's plate? >>>>>> Have you tried the same with completion and a kthread? or >>>>>> with your own workqueue, overkill but you can give it a shot. >>> I have not tried this. First I will analyze with lttng and then >>> attempts this. Does using our own workqueue reduces the latency? >>> >>>>>>> >>>>>>> return IRQ_HANDLED; >>>>>>> } >>>>>>> >>>>>>> -- >>>>>>> Thanks, >>>>>>> Sekhar >>>>>>> >>>>>>> _______________________________________________ >>>>>>> Kernelnewbies mailing list >>>>>>> Kernelnewbies at kernelnewbies.org >>>>>>> https://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies >>>>>> >>>>>> >>>>>> >>>>>> -- >>>>>> ---P.K.S >>>>>> >>>>>> _______________________________________________ >>>>>> Kernelnewbies mailing list >>>>>> Kernelnewbies at kernelnewbies.org >>>>>> https://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies >>>>> >>>>> >>>>> >>>>> -- >>>>> Ricardo Ribalda >>>>> >>>>> _______________________________________________ >>>>> Kernelnewbies mailing list >>>>> Kernelnewbies at kernelnewbies.org >>>>> https://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies >>>> >>>> >>>> >>>> -- >>>> "Do or do not. There is no try" >>>> Yoda Master >>>> >>>> _______________________________________________ >>>> Kernelnewbies mailing list >>>> Kernelnewbies at kernelnewbies.org >>>> https://lists.kernelnewbies.org/mailman/listinfo/kernelnewbies >>> >>> >>> >>> -- >>> Thanks, >>> Sekhar >> >> >> >> -- >> "Do or do not. There is no try" >> Yoda Master > > > > -- > Thanks, > Sekhar -- "Do or do not. There is no try" Yoda Master ^ permalink raw reply [flat|nested] 10+ messages in thread
* doubt on schedule_work() - work task getting scheduled lately 2016-07-29 10:32 doubt on schedule_work() - work task getting scheduled lately Muni Sekhar 2016-07-29 10:44 ` Pranay Srivastava @ 2016-08-05 5:44 ` Mulyadi Santosa 1 sibling, 0 replies; 10+ messages in thread From: Mulyadi Santosa @ 2016-08-05 5:44 UTC (permalink / raw) To: kernelnewbies On Fri, Jul 29, 2016 at 5:32 PM, Muni Sekhar <munisekharrms@gmail.com> wrote: > Hi All, > > I have a doubt regarding the workqueue scheduling. > > I am using the workqueue for processing the Rx Interrupt data. I am > calling schedule_work() on receiving the Rx interrupt from hardware. > > I calculated the time between calling the schedule_work() and > workqueue task actually getting executed, Here I see many cases of > less than 100 us(It is fairly good). > > But sometimes I see 10?s of ms and a lot in the 100?s of ms. I have > seen over 0.5 secs too. I would like to know why does sometimes kernel > takes longer time(in milli seconds) to schedule it? Is there any way > to reduce this time gap? > > > My code: > > static void my_workqueuetask(struct work_struct *work) > { > printk("In %s() \n",__func__); > > mutex_lock(&bh_mutex); > > //Do something here > > mutex_unlock(&bh_mutex); > } > > > static irqreturn_t my_irq_handler(int irq, void *dev) > { > ??; > > if(Rx Interrupt) > schedule_work(&rx_work); > > return IRQ_HANDLED; > } > > -- > Thanks, > Sekhar > > Hi Sekhar In general, in non real time kernel, there is no way you can make sure your work will be scheduled after N seconds. Have you done simple statistic calculation how much % it is slower than 100 us, and how much % it is faster than 100 us? IMHO, if slower % is lower than 1% of overall sample, I think it is still acceptable, but this is up to your judgement BTW, like other said too, that mutex_lock, have you also measured how long, by average, the lock is taken? -- regards, Mulyadi Santosa Freelance Linux trainer and consultant blog: the-hydra.blogspot.com training: mulyaditraining.blogspot.com -------------- next part -------------- An HTML attachment was scrubbed... URL: http://lists.kernelnewbies.org/pipermail/kernelnewbies/attachments/20160805/5649a508/attachment-0001.html ^ permalink raw reply [flat|nested] 10+ messages in thread
* doubt on schedule_work() - work task getting scheduled lately
@ 2016-07-29 9:39 Muni Sekhar
0 siblings, 0 replies; 10+ messages in thread
From: Muni Sekhar @ 2016-07-29 9:39 UTC (permalink / raw)
To: linux-kernel
Hi All,
I have a doubt regarding the workqueue scheduling.
I am using the workqueue for processing the Rx Interrupt data. I am
calling schedule_work() on receiving the Rx interrupt from hardware.
I calculated the time between calling the schedule_work() and
workqueue task actually getting executed, Here I see many cases of
less than 100 us(It is fairly good).
But sometimes I see 10’s of ms and a lot in the 100’s of ms. I have
seen over 0.5 secs too. I would like to know why does sometimes kernel
takes longer time(in milli seconds) to schedule it? Is there any way
to reduce this time gap?
My code:
static void my_workqueuetask(struct work_struct *work)
{
printk("In %s() \n",__func__);
mutex_lock(&rx_bh_mutex);
//Do something here
mutex_lock(&rx_bh_mutex);
}
static irqreturn_t my_irq_handler(int irq, void *dev)
{
……;
if(Rx Interrupt)
schedule_work(&rx_work);
return IRQ_HANDLED;
}
--
Thanks,
Sekhar
^ permalink raw reply [flat|nested] 10+ messages in threadend of thread, other threads:[~2016-08-05 13:09 UTC | newest] Thread overview: 10+ messages (download: mbox.gz / follow: Atom feed) -- links below jump to the message on this page -- 2016-07-29 10:32 doubt on schedule_work() - work task getting scheduled lately Muni Sekhar 2016-07-29 10:44 ` Pranay Srivastava 2016-07-29 13:48 ` Ricardo Ribalda Delgado 2016-07-29 15:35 ` Daniel. 2016-08-01 10:32 ` Muni Sekhar 2016-08-01 13:04 ` Daniel. 2016-08-05 7:22 ` Muni Sekhar 2016-08-05 13:09 ` Daniel. 2016-08-05 5:44 ` Mulyadi Santosa -- strict thread matches above, loose matches on Subject: below -- 2016-07-29 9:39 Muni Sekhar
This is an external index of several public inboxes, see mirroring instructions on how to clone and mirror all data and code used by this external index.