Hello all, I am working on writing a console driver for an OS on Xen and am running into a strange delay regarding console output. I am using the ring buffer (not the hypercall) for output, and signaling with HYPERVISOR_event_channel_op after every character is written. The delay seems to occur _only_sometimes_ after a character is output. I have tracked it using GDB and noted that the delay happens after the characters are put into the ring buffer and the event channel is notified. Sometimes, the character appears instantly in the console output. Other times, it takes several seconds to show up. I am using the standard xenconsole reader. Is there some sort of time-based buffering that occurs in the console output buffer? The result I would like to achieve is latency-free console output. Thanks, dan _______________________________________________ Xen-devel mailing list Xen-devel@lists.xensource.com http://lists.xensource.com/xen-devel
Output to the console is rate-limited to 30 event-channel notifications per 200ms. You could be hitting that limit: see the RATE_LIMIT_ values in tools/console/daemon/io.c: the logic is fairly easily defeated to test if that is what is stalling you. Batching your notifications a bit (e.g., once per console line) might actually smooth things out a bit. -- Keir On 14/3/08 00:26, "Dan Kuebrich" <dan.kuebrich@gmail.com> wrote:> Hello all, > > I am working on writing a console driver for an OS on Xen and am running into > a strange delay regarding console output. I am using the ring buffer (not the > hypercall) for output, and signaling with HYPERVISOR_event_channel_op after > every character is written. > > The delay seems to occur _only_sometimes_ after a character is output. I have > tracked it using GDB and noted that the delay happens after the characters are > put into the ring buffer and the event channel is notified. Sometimes, the > character appears instantly in the console output. Other times, it takes > several seconds to show up. > > I am using the standard xenconsole reader. Is there some sort of time-based > buffering that occurs in the console output buffer? > > The result I would like to achieve is latency-free console output. > > Thanks, > dan > > > _______________________________________________ > Xen-devel mailing list > Xen-devel@lists.xensource.com > http://lists.xensource.com/xen-devel_______________________________________________ Xen-devel mailing list Xen-devel@lists.xensource.com http://lists.xensource.com/xen-devel
Keir, Thanks for the quick response. I did a little investigation and still have questions about this. 1. Is this rate-limiting implemented in xen 3.0.3 (which is what I''m running)? I couldn''t find anything in console/daemon/io.c. 2. If rate limiting were implemented, it doesn''t seem to be flooded entirely. There should be only 1-2 event-channel notifications occurring per second. Additionally, sometimes printing one character, waiting a second, then printing a second character (and thus triggering another notification) does not "flush" them--it still takes several seconds after before flushing occurs. Is there another possibility for what is going on here? dan On Fri, Mar 14, 2008 at 5:07 AM, Keir Fraser <keir.fraser@eu.citrix.com> wrote:> Output to the console is rate-limited to 30 event-channel notifications > per 200ms. You could be hitting that limit: see the RATE_LIMIT_ values in > tools/console/daemon/io.c: the logic is fairly easily defeated to test if > that is what is stalling you. Batching your notifications a bit (e.g., > once per console line) might actually smooth things out a bit. > > -- Keir > > > On 14/3/08 00:26, "Dan Kuebrich" <dan.kuebrich@gmail.com> wrote: > > Hello all, > > I am working on writing a console driver for an OS on Xen and am running > into a strange delay regarding console output. I am using the ring buffer > (not the hypercall) for output, and signaling with > HYPERVISOR_event_channel_op after every character is written. > > The delay seems to occur _only_sometimes_ after a character is output. I > have tracked it using GDB and noted that the delay happens after the > characters are put into the ring buffer and the event channel is notified. > Sometimes, the character appears instantly in the console output. Other > times, it takes several seconds to show up. > > I am using the standard xenconsole reader. Is there some sort of > time-based buffering that occurs in the console output buffer? > > The result I would like to achieve is latency-free console output. > > Thanks, > dan > > ------------------------------ > _______________________________________________ > Xen-devel mailing list > Xen-devel@lists.xensource.com > http://lists.xensource.com/xen-devel > > >_______________________________________________ Xen-devel mailing list Xen-devel@lists.xensource.com http://lists.xensource.com/xen-devel
Sounds like it isn¹t due to the rate limiting then. I¹m not sure what it might be in that case. Is your system uniprocessor and hence this could be scheduling latency? -- Keir On 14/3/08 19:19, "Dan Kuebrich" <dan.kuebrich@gmail.com> wrote:> Keir, > > Thanks for the quick response. I did a little investigation and still have > questions about this. > > 1. Is this rate-limiting implemented in xen 3.0.3 (which is what I''m running)? > I couldn''t find anything in console/daemon/io.c. > > 2. If rate limiting were implemented, it doesn''t seem to be flooded entirely. > There should be only 1-2 event-channel notifications occurring per second. > Additionally, sometimes printing one character, waiting a second, then > printing a second character (and thus triggering another notification) does > not "flush" them--it still takes several seconds after before flushing occurs. > > Is there another possibility for what is going on here? > > dan > > On Fri, Mar 14, 2008 at 5:07 AM, Keir Fraser <keir.fraser@eu.citrix.com> > wrote: >> Output to the console is rate-limited to 30 event-channel notifications per >> 200ms. You could be hitting that limit: see the RATE_LIMIT_ values in >> tools/console/daemon/io.c: the logic is fairly easily defeated to test if >> that is what is stalling you. Batching your notifications a bit (e.g., once >> per console line) might actually smooth things out a bit. >> >> -- Keir >> >> >> On 14/3/08 00:26, "Dan Kuebrich" <dan.kuebrich@gmail.com> wrote: >> >>> Hello all, >>> >>> I am working on writing a console driver for an OS on Xen and am running >>> into a strange delay regarding console output. I am using the ring buffer >>> (not the hypercall) for output, and signaling with >>> HYPERVISOR_event_channel_op after every character is written. >>> >>> The delay seems to occur _only_sometimes_ after a character is output. I >>> have tracked it using GDB and noted that the delay happens after the >>> characters are put into the ring buffer and the event channel is notified. >>> Sometimes, the character appears instantly in the console output. Other >>> times, it takes several seconds to show up. >>> >>> I am using the standard xenconsole reader. Is there some sort of time-based >>> buffering that occurs in the console output buffer? >>> >>> The result I would like to achieve is latency-free console output. >>> >>> Thanks, >>> dan >>> >>> >>> _______________________________________________ >>> Xen-devel mailing list >>> Xen-devel@lists.xensource.com >>> http://lists.xensource.com/xen-devel >> > >_______________________________________________ Xen-devel mailing list Xen-devel@lists.xensource.com http://lists.xensource.com/xen-devel
Keir,
Your comment about a possible scheduling delay made me think about the idle
loop of the fledgling operating system. I discovered that I needed to add a
SCHEDOP_yield call in the "no runnable threads right now" loop in the
scheduler--that solved the output delay. However, if I put the call where
it intuitively seems it should go, the delay still exists, whereas if I put
it in a slightly different location, it works fine.
void sched_switch(void)
{
kthread_t *oldthr = curthr, *newthr;
evtchn_mask_t evtchn_mask;
evtchn_mask_save(&evtchn_mask);
// while no runnable threads are available...
while (ktqueue_empty(&kg_runq)) {
evtchn_unmask_all();
//XXX this is where I think the yield should be XXX
evtchn_mask_restore(&evtchn_mask);
// and this is where I put it to make it work right
HYPERVISOR_sched_op(SCHEDOP_yield, 0);
}
// ... perform context switch, restore event channel mask of new thread
...
}
Anyone have an idea why this is? And is this even the right way to idle in
a Xen OS? It''s working now, but I''m not very satisfied by the
solution.
Thanks again,
dan
On Fri, Mar 14, 2008 at 3:37 PM, Keir Fraser <keir.fraser@eu.citrix.com>
wrote:
> Sounds like it isn''t due to the rate limiting then. I''m
not sure what it
> might be in that case. Is your system uniprocessor and hence this could be
> scheduling latency?
>
> -- Keir
>
>
> On 14/3/08 19:19, "Dan Kuebrich" <dan.kuebrich@gmail.com>
wrote:
>
> Keir,
>
> Thanks for the quick response. I did a little investigation and still
> have questions about this.
>
> 1. Is this rate-limiting implemented in xen 3.0.3 (which is what
I''m
> running)? I couldn''t find anything in console/daemon/io.c.
>
> 2. If rate limiting were implemented, it doesn''t seem to be
flooded
> entirely. There should be only 1-2 event-channel notifications occurring
> per second. Additionally, sometimes printing one character, waiting a
> second, then printing a second character (and thus triggering another
> notification) does not "flush" them--it still takes several
seconds after
> before flushing occurs.
>
> Is there another possibility for what is going on here?
>
> dan
>
> On Fri, Mar 14, 2008 at 5:07 AM, Keir Fraser
<keir.fraser@eu.citrix.com>
> wrote:
>
> Output to the console is rate-limited to 30 event-channel notifications
> per 200ms. You could be hitting that limit: see the RATE_LIMIT_ values in
> tools/console/daemon/io.c: the logic is fairly easily defeated to test if
> that is what is stalling you. Batching your notifications a bit (e.g.,
> once per console line) might actually smooth things out a bit.
>
> -- Keir
>
>
> On 14/3/08 00:26, "Dan Kuebrich" <dan.kuebrich@gmail.com>
wrote:
>
> Hello all,
>
> I am working on writing a console driver for an OS on Xen and am running
> into a strange delay regarding console output. I am using the ring buffer
> (not the hypercall) for output, and signaling with
> HYPERVISOR_event_channel_op after every character is written.
>
> The delay seems to occur _only_sometimes_ after a character is output. I
> have tracked it using GDB and noted that the delay happens after the
> characters are put into the ring buffer and the event channel is notified.
> Sometimes, the character appears instantly in the console output. Other
> times, it takes several seconds to show up.
>
> I am using the standard xenconsole reader. Is there some sort of
> time-based buffering that occurs in the console output buffer?
>
> The result I would like to achieve is latency-free console output.
>
> Thanks,
> dan
>
> ------------------------------
> _______________________________________________
> Xen-devel mailing list
> Xen-devel@lists.xensource.com
> http://lists.xensource.com/xen-devel
>
>
>
>
>
>
_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xensource.com
http://lists.xensource.com/xen-devel
I don¹t know what your evtchn_mask_* operations do, so I cannot judge why changing the location of the yield makes a difference. The correct thing to do in an idle loop is block: 1. Disable event delivery (evtchn_upcall_mask). 2. Check for work to do (in your case check for threads on run queue) 3. SCHEDOP_block (automatically reenables event delivery) When you block you stop receiving periodic timer ticks. If you wake up threads on timer ticks then you may want to set a one-shot timer before blocking. -- Keir On 16/3/08 00:18, "Dan Kuebrich" <dan.kuebrich@gmail.com> wrote:> Keir, > > Your comment about a possible scheduling delay made me think about the idle > loop of the fledgling operating system. I discovered that I needed to add a > SCHEDOP_yield call in the "no runnable threads right now" loop in the > scheduler--that solved the output delay. However, if I put the call where it > intuitively seems it should go, the delay still exists, whereas if I put it in > a slightly different location, it works fine. > > void sched_switch(void) > { > kthread_t *oldthr = curthr, *newthr; > > evtchn_mask_t evtchn_mask; > evtchn_mask_save(&evtchn_mask); > > // while no runnable threads are available... > while (ktqueue_empty(&kg_runq)) { > > evtchn_unmask_all(); > > //XXX this is where I think the yield should be XXX > > evtchn_mask_restore(&evtchn_mask); > > // and this is where I put it to make it work right > HYPERVISOR_sched_op(SCHEDOP_yield, 0); > } > // ... perform context switch, restore event channel mask of new thread > ... > } > > Anyone have an idea why this is? And is this even the right way to idle in a > Xen OS? It''s working now, but I''m not very satisfied by the solution. > > Thanks again, > dan > > > On Fri, Mar 14, 2008 at 3:37 PM, Keir Fraser <keir.fraser@eu.citrix.com> > wrote: >> Sounds like it isn''t due to the rate limiting then. I''m not sure what it >> might be in that case. Is your system uniprocessor and hence this could be >> scheduling latency? >> >> -- Keir >> >> >> On 14/3/08 19:19, "Dan Kuebrich" <dan.kuebrich@gmail.com> wrote: >> >>> Keir, >>> >>> Thanks for the quick response. I did a little investigation and still have >>> questions about this. >>> >>> 1. Is this rate-limiting implemented in xen 3.0.3 (which is what I''m >>> running)? I couldn''t find anything in console/daemon/io.c. >>> >>> 2. If rate limiting were implemented, it doesn''t seem to be flooded >>> entirely. There should be only 1-2 event-channel notifications occurring >>> per second. Additionally, sometimes printing one character, waiting a >>> second, then printing a second character (and thus triggering another >>> notification) does not "flush" them--it still takes several seconds after >>> before flushing occurs. >>> >>> Is there another possibility for what is going on here? >>> >>> dan >>> >>> On Fri, Mar 14, 2008 at 5:07 AM, Keir Fraser <keir.fraser@eu.citrix.com> >>> wrote: >>>> Output to the console is rate-limited to 30 event-channel notifications per >>>> 200ms. You could be hitting that limit: see the RATE_LIMIT_ values in >>>> tools/console/daemon/io.c: the logic is fairly easily defeated to test if >>>> that is what is stalling you. Batching your notifications a bit (e.g., once >>>> per console line) might actually smooth things out a bit. >>>> >>>> -- Keir >>>> >>>> >>>> On 14/3/08 00:26, "Dan Kuebrich" <dan.kuebrich@gmail.com> wrote: >>>> >>>>> Hello all, >>>>> >>>>> I am working on writing a console driver for an OS on Xen and am running >>>>> into a strange delay regarding console output. I am using the ring buffer >>>>> (not the hypercall) for output, and signaling with >>>>> HYPERVISOR_event_channel_op after every character is written. >>>>> >>>>> The delay seems to occur _only_sometimes_ after a character is output. I >>>>> have tracked it using GDB and noted that the delay happens after the >>>>> characters are put into the ring buffer and the event channel is notified. >>>>> Sometimes, the character appears instantly in the console output. Other >>>>> times, it takes several seconds to show up. >>>>> >>>>> I am using the standard xenconsole reader. Is there some sort of >>>>> time-based buffering that occurs in the console output buffer? >>>>> >>>>> The result I would like to achieve is latency-free console output. >>>>> >>>>> Thanks, >>>>> dan >>>>> >>>>> >>>>> _______________________________________________ >>>>> Xen-devel mailing list >>>>> Xen-devel@lists.xensource.com >>>>> http://lists.xensource.com/xen-devel >>>> >>> >>> >> > >_______________________________________________ Xen-devel mailing list Xen-devel@lists.xensource.com http://lists.xensource.com/xen-devel