Mailing List Archive

On 29/1/07 18:08, "Luke S. Crawford" <lsc@prgmr.com> wrote:

> The CPU usage of qemu-dm correlates with the speed of the scroll; exiting
> from
> the xm console does not appear to effect the cpu usage of qemu-dm- it
> will drop to 1% after several minutes.
>
> any ideas what is going on here? any ideas how I could debug this
> further?

This kind of thing can be a pain to debug. Perhaps instrument qemu-dm and
find out interesting things like how often its select() call returns due to
an event on a file descriptor rather than due to hitting the timeout?

Does the slowness happen if you are using the emulated network device at the
same time (i.e., does the event to kick back to normal behaviour have to be
a console event)?

I guess something may have crept in when we moved to using qemu's
asynchronous block i/o code...

-- Keir



_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xensource.com
http://lists.xensource.com/xen-devel

Thanks for your quick response! (mine was delayed by figuring out
oprofile.)

On Mon, 29 Jan 2007, Keir Fraser wrote:
> On 29/1/07 18:08, "Luke S. Crawford" <lsc@prgmr.com> wrote:
>> The CPU usage of qemu-dm correlates with the speed of the scroll; exiting
>> from
>> the xm console does not appear to effect the cpu usage of qemu-dm- it
>> will drop to 1% after several minutes.

> This kind of thing can be a pain to debug. Perhaps instrument qemu-dm and
> find out interesting things like how often its select() call returns due to
> an event on a file descriptor rather than due to hitting the timeout?

Okay, I have oprofile installed, and mostly figured out;

so opreport without console input:

[root@1950-2 ~]# opreport -l /usr/lib64/xen/bin/qemu-dm|head
CPU: P4 / Xeon with 2 hyper-threads, speed 3191.87 MHz (estimated)
Counted GLOBAL_POWER_EVENTS events (time during which processor is not
stopped) with a unit mask of 0x01 (mandatory) count 100000
samples % symbol name
13193 32.7483 main_loop_wait
5787 14.3648 cpu_handle_ioreq
3873 9.6138 DMA_run
1904 4.7262 qemu_get_clock
1683 4.1776 qemu_run_timers
1333 3.3088 qemu_del_timer
985 2.4450 __handle_ioreq



with console input:
[root@1950-2 ~]# opreport -l /usr/lib64/xen/bin/qemu-dm|head
CPU: P4 / Xeon with 2 hyper-threads, speed 3191.87 MHz (estimated)
Counted GLOBAL_POWER_EVENTS events (time during which processor is not
stopped) with a unit mask of 0x01 (mandatory) count 100000
samples % symbol name
11299 29.0904 main_loop_wait
4944 12.7288 cpu_handle_ioreq
3104 7.9916 DMA_run
1729 4.4515 cpu_physical_memory_rw
1481 3.8130 qemu_get_clock
1431 3.6843 iomem_index
1392 3.5838 qemu_run_timers


(those two look about the same; but the slow one, it took a good minute
to get to 3000 samples, wheras on the 'with console input' test it took
maybe 10 seconds.

hm. I need to do more reading on this oprofile in the morning (I don't
have remote access to a HVM-capable system from home at this moment)


> Does the slowness happen if you are using the emulated network device
at the
> same time (i.e., does the event to kick back to normal behaviour have to be
> a console event)?

pinging it doesn't help. (the thing that is triggering this is rsync
over the network to the drive) I will re-install with a HVM that is a
proper linux box (rather than a systemimager boot floppy) and attempt to
re-create the problem with dd or rsync in the morning.

> I guess something may have crept in when we moved to using qemu's
> asynchronous block i/o code...

It is using rsync to copy several gigabytes of files, so it is certainly
excersizing the block I/O

_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xensource.com
http://lists.xensource.com/xen-devel

On Mon, 29 Jan 2007, Keir Fraser wrote:
> On 29/1/07 18:08, "Luke S. Crawford" <lsc@prgmr.com> wrote:
>
>> The CPU usage of qemu-dm correlates with the speed of the scroll; exiting
>> from
>> the xm console does not appear to effect the cpu usage of qemu-dm- it
>> will drop to 1% after several minutes.
>>
>> any ideas what is going on here? any ideas how I could debug this
>> further?
>
> This kind of thing can be a pain to debug. Perhaps instrument qemu-dm and
> find out interesting things like how often its select() call returns due to
> an event on a file descriptor rather than due to hitting the timeout?


What tools should I use for that? I don't see how to make oprofile give
me the return values of select- in fact oprofile seems to be mostly
tailored to profiling CPU usage, and CPU usage does not appear to be the
problem here. My oprofile results (both opannotate and opreport) seem to
be largely the same in both fast and slow cases; the main difference
being that the samples accumulate much faster in 'fast' mode than in
'slow' mode.

Should I be ignoring these tools and adding logging to the code itself?


Here is some of what I got using strace:

fast:
[root@1950-2 xen-3.0.4-testing.hg]# strace -p 4013 -c
Process 4013 attached - interrupt to quit
Process 4013 detached
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
66.58 0.018072 1 27020 write
14.73 0.003997 0 74281 clock_gettime
8.81 0.002391 0 26481 select
3.77 0.001024 0 24815 read
2.70 0.000733 0 7869 munlock
2.49 0.000677 0 32441 ioctl
0.91 0.000248 0 7869 mlock
0.00 0.000000 0 496 lseek
------ ----------- ----------- --------- --------- ----------------
100.00 0.027142 201272 total

slow:
[root@1950-2 xen-3.0.4-testing.hg]# strace -p 4013 -c
Process 4013 attached - interrupt to quit
Process 4013 detached
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
29.89 0.011048 0 54389 read
27.61 0.010202 0 57631 write
15.52 0.005734 0 158975 clock_gettime
11.93 0.004408 0 73270 ioctl
11.17 0.004127 0 56038 select
2.31 0.000853 0 20786 mlock
1.58 0.000585 0 20786 munlock
0.00 0.000000 0 784 lseek
0.00 0.000000 0 6 gettimeofday
------ ----------- ----------- --------- --------- ----------------
100.00 0.036957 442665 total

It's still not what you are asking for, but somewhat interesting, I hope.
I do notice that the 'fast' spends a whole lot more time in write.

(strace seems to be rather high-overhead; running strace, the 'fast' is
much slower than the normal 'slow', and I'm not seeing much consistancy
here, so perhaps strace is the wrong tool for the job?)



_______________________________________________
Xen-devel mailing list
Xen-devel@lists.xensource.com
http://lists.xensource.com/xen-devel