[Spice-devel] [PATCH 8/9] worker: make sure we dispatch after releasing items
Jonathon Jongsma
jjongsma at redhat.com
Mon Jan 4 08:51:04 PST 2016
On Tue, 2015-12-22 at 11:53 -0500, Frediano Ziglio wrote:
> >
> > On Mon, 2015-12-21 at 09:54 -0600, Jonathon Jongsma wrote:
> > > On Mon, 2015-12-21 at 10:17 -0500, Frediano Ziglio wrote:
> > > > >
> > > > > On Fri, 2015-12-18 at 06:10 -0500, Frediano Ziglio wrote:
> > > > > > > Hi
> > > > > > >
> > > > > > > ----- Original Message -----
> > > > > > > > On Wed, 2015-12-16 at 18:16 -0500, Marc-André Lureau wrote:
> > > > > > > > > Hi
> > > > > > > > >
> > > > > > > > > ----- Original Message -----
> > > > > > > > > I actually think that was it. The worker thread may currently
> > > > > > > > > block
> > > > > > > > > because
> > > > > > > > > the client is too slow. But then, when we release item, the
> > > > > > > > > pipe
> > > > > > > > > is
> > > > > > > > > going
> > > > > > > > > to
> > > > > > > > > be smaller hopefully, and thus we can try to dispatch again
> > > > > > > > > without
> > > > > > > > > waiting
> > > > > > > > > for the timeout. (waiting for timers can really degrade
> > > > > > > > > performances
> > > > > > > > > in
> > > > > > > > > some
> > > > > > > > > cases, like you see today with the qemu virgl timer, but
> > > > > > > > > that's
> > > > > > > > > another
> > > > > > > > > story where I can show you figures when we merge gl scanounts
> > > > > > > > > in
> > > > > > > > > spice
> > > > > > > > > ;)
> > > > > > > >
> > > > > > > > Then I'm still confused. In the old loop, we had a very explicit
> > > > > > > > sequence
> > > > > > > > of
> > > > > > > > behavior. For each loop:
> > > > > > > >
> > > > > > > > 1 calculate timeout for poll() function
> > > > > > > > 2 poll() fds with timeout from step 1
> > > > > > > > 3 service expired timers
> > > > > > > > 4 handle fd watch events
> > > > > > > > 5 process cursor commands from guest
> > > > > > > > 6 process display commands from guest
> > > > > > > > 7 push queued messages to clients
> > > > > > > > 8 GOTO 1
> > > > > > > >
> > > > > > > > After pushing the queued messages to the client, we did not go
> > > > > > > > back
> > > > > > > > and
> > > > > > > > handle
> > > > > > > > cursor and display commands again. We went back to the top of
> > > > > > > > the
> > > > > > > > loop
> > > > > > > > and
> > > > > > > > did a
> > > > > > > > poll with timeout again. So I fail to see why the glib loop
> > > > > > > > needs
> > > > > > > > to
> > > > > > > > short
> > > > > > > > -circuit the timeout and return to step 5 when the old design
> > > > > > > > didn't.
> > > > > > > >
> > > > > > > > Or is this change unrelated to the new glib loop and the worker
> > > > > > > > has
> > > > > > > > simply
> > > > > > > > always been too slow even with the old loop implementation?
> > > > > > > >
> > > > > > >
> > > > > > > I wouldn't say "too slow", and I wouldn't try to mimic the old
> > > > > > > code
> > > > > > > either.
> > > > > > > For me the goal is simply to process the pipe/command as fast as
> > > > > > > possible
> > > > > > > and if possible, get rid of timeouts.
> > > > > >
> > > > > > I can understand that not mimic can be better but at the moment this
> > > > > > is
> > > > > > causing
> > > > > > a bit of regressions and this patch was trying to avoid some (I
> > > > > > think).
> > > > > >
> > > > > > I looked more deeply at glib code. The sources are stored (appended)
> > > > > > in
> > > > > > multiple
> > > > > > list (each for every priority and given at the moment we are using a
> > > > > > single
> > > > > > priority which was similar to former code anyway). Considering that
> > > > > > the
> > > > > > processing
> > > > > > code is registered at worker initialization and that watches are
> > > > > > recreated
> > > > > > when
> > > > > > event masks are updated this possibly lead the watched to be after
> > > > > > the
> > > > > > process
> > > > > > leading the loop to be:
> > > > > >
> > > > > > 1 calculate timeout for poll() function
> > > > > > 2 poll() fds with timeout from step 1
> > > > > > 3 process cursor commands from guest
> > > > > > 4 process display commands from guest
> > > > > > 5 push queued messages to clients
> > > > > > 6 service expired timers
> > > > > > 7 handle fd watch events
> > > > > > 8 GOTO 1
> > > > > > (not sure about timers but are not that frequent).
> > > > > > This obviously make stuff worse as after step 7 you have to wait the
> > > > > > poll
> > > > > > (2)
> > > > > > to get commands processed again.
> > > > > > I'm not saying that the patch address also some other issues but
> > > > > > that
> > > > > > the
> > > > > > glib
> > > > > > code
> > > > > > actually make this patch more useful (that is glib have
> > > > > > regressions).
> > > > > >
> > > > > > On a more wide looking. What are this (and possibly "worker: avoid
> > > > > > server
> > > > > > hanging
> > > > > > when no client are connected.") patch trying to fix?
> > > > > > Basically trying to handle slow clients. On fast clients you don't
> > > > > > have
> > > > > > many
> > > > > > issues.
> > > > > > Pipe queue is (or should be) quite small and all commands are
> > > > > > processed.
> > > > > > But
> > > > > > on slow
> > > > > > clients we process till the queue reach a given size. I honestly
> > > > > > don't
> > > > > > have
> > > > > > all
> > > > > > knowledge on what happen next. When you do a push on RedChannel you
> > > > > > try
> > > > > > to
> > > > > > send as
> > > > > > many items till network queue is full. If the client is just not
> > > > > > processing
> > > > > > you can
> > > > > > only add items to the queue. After a while the limit is reached and
> > > > > > to
> > > > > > avoid
> > > > > > queuing
> > > > > > indefinitely you stop processing commands. Now I would have some
> > > > > > questions:
> > > > > > - what happen in the guest? Just after a while the screen get no
> > > > > > more
> > > > > > updates?
> > > > > > And if the client ask for an update?
> > > > > > - does item collapsing occurs only if client is not connected? I
> > > > > > think
> > > > > > that
> > > > > > what should
> > > > > > happen is that if there are too items items should be collapsed
> > > > > > (reduced
> > > > > > drawing
> > > > > > on surfaces) and processing should continue.
> > > > > > - what happen if client keep sending request that trigger appending
> > > > > > items
> > > > > > but
> > > > > > avoid
> > > > > > the read? Can a DoS be triggered?
> > > > > >
> > > > > > Frediano
> > > > >
> > > > >
> > > > >
> > > > > So I did some very simplistic testing here. Basically I looked at the
> > > > > red_process_display() function to see how often we encountered a full
> > > > > pipe
> > > > > queue
> > > > > (since that is the situation that Marc-Andre thinks this patch is
> > > > > trying
> > > > > to
> > > > > improve). I was curious how often this happened, so I just
> > > > > instrumented
> > > > > the
> > > > > code
> > > > > to count how many times we called red_process_display() and how many
> > > > > of
> > > > > those
> > > > > times we returned from this function due to a full queue (rather than
> > > > > because
> > > > > there were no more commands to process). Here's the patch:
> > > > >
> > > > > diff --git a/server/red-worker.c b/server/red-worker.c
> > > > > index dfaf4ba..dec635d 100644
> > > > > --- a/server/red-worker.c
> > > > > +++ b/server/red-worker.c
> > > > > @@ -229,7 +235,10 @@ static int red_process_display(RedWorker *worker,
> > > > > uint32_t
> > > > > max_pipe_size, int *r
> > > > > QXLCommandExt ext_cmd;
> > > > > int n = 0;
> > > > > uint64_t start = spice_get_monotonic_time_ns();
> > > > > + static int total = 0;
> > > > > + static int full = 0;
> > > > >
> > > > > + total++;
> > > > > if (!worker->running) {
> > > > > *ring_is_empty = TRUE;
> > > > > return n;
> > > > > @@ -335,6 +344,9 @@ static int red_process_display(RedWorker *worker,
> > > > > uint32_t
> > > > > max_pipe_size, int *r
> > > > > return n;
> > > > > }
> > > > > }
> > > > > + full++;
> > > > > + fprintf(stderr, "display channel exceeded max pipe size: %i/%i
> > > > > (%g)\n",
> > > > > + full, total, (double)full / total * 100.0);
> > > > > return n;
> > > > > }
> > > > >
> > > > >
> > > > > This was my procedure:
> > > > >
> > > > > - Boot RHEL7 guest
> > > > > - wait for boot sequence to finish
> > > > > - log into GNOME
> > > > > - start web browser, open a page
> > > > > - open another page in another tab
> > > > > - open video player and play video in full screen
> > > > > - enable second display
> > > > > - resize second display
> > > > > - disable second display
> > > > > - exit video player
> > > > > - shut down guest
> > > > >
> > > > > I did this same test with the current master branch, with the glib
> > > > > loop
> > > > > patch
> > > > > applied, and also with this patch on top of the glib loop patch.
> > > > >
> > > > > What I noticed is that during the boot sequence and the shutdown
> > > > > sequence
> > > > > (when
> > > > > we're in a VT and text is scrolling up the screen), we hit the queue
> > > > > limit
> > > > > quite
> > > > > frequently. In fact, nearly 30% of the time that we call
> > > > > red_process_display(),
> > > > > we return because our pipe queue is full. However, after X has started
> > > > > and
> > > > > we're
> > > > > in the desktop, we never hit a full-queue condition. When I shut down
> > > > > the
> > > > > guest,
> > > > > it briefly returns to the VT until it powers down, and we again hit
> > > > > some
> > > > > full
> > > > > -queue conditions.
> > > > >
> > > > > This was true of both the old loop and the new glib loop (with and
> > > > > without
> > > > > the
> > > > > patch).
> > > > >
> > > > > There were some differences between the old and new loop. In
> > > > > particular,
> > > > > the
> > > > > new
> > > > > glib loop called red_process_display() more times in roughly the same
> > > > > elapsed
> > > > > time. It also had a higher percentage of calls that returned because
> > > > > the
> > > > > queue
> > > > > was full (but again, this did not happen during "normal" operation,
> > > > > but
> > > > > only
> > > > > during the boot and shutdown phase). The glib loop with this patch on
> > > > > top
> > > > > had
> > > > > roughly the same percentage as the glib loop on its own, but the total
> > > > > number
> > > > > of
> > > > > calls to red_process_display() was higher, unsurprisingly.
> > > > >
> > > > >
> > > > > Here is some example output:
> > > > >
> > > > > Old loop: http://ur1.ca/ocnyn
> > > > > Glib loop: http://ur1.ca/ocnyp
> > > > > glib loop with this patch applied: http://ur1.ca/oco1u
> > > > >
> > > > > Notice that lines such as this indicate that GDM has started or I've
> > > > > logged
> > > > > into
> > > > > GNOME:
> > > > >
> > > > > main_channel_handle_parsed: agent start
> > > > >
> > > > > Then I use the desktop for about a minute before shutting down again.
> > > > > No
> > > > > more
> > > > > log messages are printed until shutdown begins.
> > > > >
> > > > > I also did another test where I used the guest "normally" (browsing
> > > > > internet,
> > > > > watching videos, writing text in libreoffice, etc) for quite a while,
> > > > > and
> > > > > still
> > > > > never triggered the full-queue condition.
> > > > >
> > > > > I'm not sure what conclusions to draw from this exactly. There is
> > > > > probably
> > > > > some
> > > > > better way to test this. Perhaps we should test how long a pipe item
> > > > > stays
> > > > > in
> > > > > the queue before it is sent.
> > > > >
> > > > > Jonathon
> > > > >
> > > >
> > > > That's great!
> > > >
> > > > I'm quite scare about the loop counts using Glib. Mainly looks like loop
> > > > is
> > > > executed twice as much (with possible cpu usage increased).
> > >
> > > Yeah, with the plain glib loop it's about 1.5x, but with the additional
> > > wakeup
> > > -after-releasing-a-pipe-item patch, it's closer to double.
> > >
> > >
> > > >
> > > > I agree would be helpful to see the latency of the items.
> > > >
> > > > Did you try increasing client latency or decreasing bandwidth?
> > > > I think replay utility could be useful for these tests (didn't try).
> > > >
> > > > Frediano
> > >
> > >
> > >
> > > Nope, I didn't try any latency or bandwidth adjustments yet. This was just
> > > a
> > > first step to get a rough comparison and then figure out exactly what we
> > > should
> > > be testing. I haven't actually used the reply utility much yet, so I may
> > > have
> > > some questions about it when I start using it. But that's a good
> > > suggestion.
> > >
> > > Jonathon
> >
> >
> > OK, here's some initial test results showing the amount of time a pipe item
> > waits in the queue before being sent out. Basically I save the time when a
> > pipe
> > item is is added to the queue, and then check the time when that item is
> > sent
> > to
> > the client. The procedure I used to test is basically the same as that
> > describe
> > above for my previous test. I
> >
> > Old loop:
> > ========
> > - First run:
> > avg=1.64109ms, max=56.881ms, min=5.4e-05ms (n=85801)
> >
> > - second run (with queue time distribution):
> > avg=1.66152ms, max=60.9958ms, min=4.1e-05ms (n=84801) queue time
> > distribution: <0.1ms=3495, <0.2ms=509, <0.5ms=7035,
> > <1ms=36476, <2ms=26316, <5ms=7399, <10ms=1285, <20ms=1365, <50ms=914,
> > >50ms=7
> >
> >
> >
> > glib loop:
> > =========
> > - First run:
> > avg=1.78949ms, max=49.901ms, min=4.8e-05ms (n=85801)
> >
> > - second run (with queue time distribution):
> > avg=1.67802ms, max=65.0128ms, min=3.9e-05ms (n=87601)
> > queue time distribution: <0.1ms=4313, <0.2ms=500, <0.5ms=6088,
> > <1ms=35567,
> > <2ms=29102, <5ms=8284, <10ms=1502, <20ms=1224, <50ms=1012, >50ms=9
> >
> >
> > glib loop with this patch applied:
> > =================================
> > - First run:
> > avg=1.76456ms, max=65.865ms, min=4.8e-05ms (n=86601)
> >
> > - second run (with queue time distribution):
> > avg=1.80822ms, max=53.4864ms, min=5.5e-05ms (n=86001)
> > queue time distribution: <0.1ms=3393, <0.2ms=500, <0.5ms=6166,
> > <1ms=31334,
> > <2ms=30842, <5ms=9671, <10ms=1636, <20ms=1414, <50ms=1037, >50ms=8
> >
> >
> > As you can see, the stats vary a bit between runs. It's not obviously better
> > or
> > worse between the old loop and the new glib loop. The average queue times
> > are
> > just slightly higher on the glib ones, but I'd have to do more test runs to
> > know
> > whether that was statistically significant.
> >
> > One thing I did notice was that during the (VT-based) boot phase, the max
> > queue
> > time tended to be only about 20ms, but once the graphical environment
> > started
> > up, I started getting more longer queue times. This could just be due to the
> > increased CPU load of the host, though.
> >
>
> I'm quite impressed that after the release patch the average was not lower!
> Honestly looks like is quite hard to have consistent results.
> Even using same input and removing guest cpu (using replay utility) the data
> can change quite a lot. Would be possibly helpful to have a less multitasking
> environment (I do the test on my laptop with all running).
>
> > Also worth noting is that if the queue is full, we simply don't create pipe
> > items. So, it's possible that qxl commands are waiting longer to be
> > processed,
> > but that doesn't show up on these statistics.
> >
>
> Right, I think with replay utility taking into account that command would
> be the same would make easier to understand which algorithm loose more
> commands.
>
> >
> > Somewhat unrelated question: Does anybody know how the value of 50 was
> > chosen
> > for MAX_PIPE_SIZE? If we could increase that value a bit, it would reduce
> > the
> > number of times we'd hit the full queue scenario. Of course it would also
> > increase memory use, but maybe we're willing to trade some additional memory
> > usage in the host to avoid blocking the guest regularly due to unhandled qxl
> > commands.
> >
>
> Yes, but it's just a workaround. No idea where the MAX_PIPE_SIZE came and
> looking at git history is useless (came from first git import).
>
> > (instrumentation patch here if you're intersted: http://ur1.ca/ocsfl)
> >
>
> Interesting! Just I would save the total queue, not the average. Every time
> you compute and save you loose a bit of precision (actually involving
> conversion
> from gdouble to guint64 you have a truncation). But error should be quite
> similar
> in all cases and actually should be on average n_sent / 4 nanoseconds.
Oops. it certainly would be a better idea to avoid losing precision like that.
Not sure what I was thinking. But as you say, even if the numbers aren't
accurate they should at least be somewhat comparable.
So I recorded a spice session and used the replay utility to compare these
patches yet again. I did six runs of each and averaged the stats from the six
runs to come up with a slightly more consistent number for each scenario. Here
are the results:
Old Loop:
Avg queue time: 4.750275ms
Max queue time: 177.0363333333ms
<0.1ms: 1654.1666666667
<0.2ms: 1040.3333333333
<0.5ms: 14759.3333333333
<1ms: 44561.6666666667
<2ms: 11806.6666666667
<5ms: 4091
<10ms: 1045.6666666667
<20ms: 1026
<50ms: 3006.3333333333
>50ms: 2843.1666666667
Glib Loop:
Avg queue time: 4.6821966667
Max queue time: 178.8768333333
<0.1ms: 1832.6666666667
<0.2ms: 753.3333333333
<0.5ms: 12149.5
<1ms: 41183.1666666667
<2ms: 17457.6666666667
<5ms: 4774
<10ms: 1084.8333333333
<20ms: 1057.3333333333
<50ms: 2816.5
>50ms: 2692
Glib Loop with patch:
Avg queue time: 5.6059783333
Max queue time: 195.8168333333
<0.1ms: 2083.5
<0.2ms: 710
<0.5ms: 9365.3333333333
<1ms: 37973.8333333333
<2ms: 19989.6666666667
<5ms: 7505.6666666667
<10ms: 1193.5
<20ms: 920.3333333333
<50ms: 2540.3333333333
>50ms: 3485.5
The old loop and the glib loop are actually quite comparable. The glib loop with
the patch seems to be significantly worse in average queue time.
More information about the Spice-devel
mailing list