| Message ID | 1491384478-12325-1-git-send-email-lidongchen@tencent.com (mailing list archive) |
|---|---|
| State | New, archived |
| Headers | show |
On Wed, Apr 05, 2017 at 05:27:58PM +0800, jemmy858585@gmail.com wrote: > From: Lidong Chen <lidongchen@tencent.com> > > when migration with high speed, mig_save_device_bulk invoke > bdrv_is_allocated too frequently, and cause vnc reponse slowly. > this patch limit the time used for bdrv_is_allocated. Can you explain why calling bdrv_is_allocated is impacting VNC performance ? Migration is running in a background thread, so shouldn't be impacting the main thread which handles VNC, unless the block layer is perhaps acquiring the global qemu lock ? I wouldn't expect such a lock to be held for just the bdrv_is_allocated call though. Regards, Daniel
On Wed, Apr 5, 2017 at 5:34 PM, Daniel P. Berrange <berrange@redhat.com> wrote: > On Wed, Apr 05, 2017 at 05:27:58PM +0800, jemmy858585@gmail.com wrote: >> From: Lidong Chen <lidongchen@tencent.com> >> >> when migration with high speed, mig_save_device_bulk invoke >> bdrv_is_allocated too frequently, and cause vnc reponse slowly. >> this patch limit the time used for bdrv_is_allocated. > > Can you explain why calling bdrv_is_allocated is impacting VNC performance ? > bdrv_is_allocated is called after qemu_mutex_lock_iothread. if (bmds->shared_base) { qemu_mutex_lock_iothread(); aio_context_acquire(blk_get_aio_context(bb)); /* Skip unallocated sectors; intentionally treats failure as * an allocated sector */ while (cur_sector < total_sectors && !bdrv_is_allocated(blk_bs(bb), cur_sector, MAX_IS_ALLOCATED_SEARCH, &nr_sectors)) { cur_sector += nr_sectors; } aio_context_release(blk_get_aio_context(bb)); qemu_mutex_unlock_iothread(); } and the main thread is also call qemu_mutex_lock_iothread. #0 0x00007f107322f264 in __lll_lock_wait () from /lib64/libpthread.so.0 #1 0x00007f107322a508 in _L_lock_854 () from /lib64/libpthread.so.0 #2 0x00007f107322a3d7 in pthread_mutex_lock () from /lib64/libpthread.so.0 #3 0x0000000000949ecb in qemu_mutex_lock (mutex=0xfc51a0) at util/qemu-thread-posix.c:60 #4 0x0000000000459e58 in qemu_mutex_lock_iothread () at /root/qemu/cpus.c:1516 #5 0x0000000000945322 in os_host_main_loop_wait (timeout=28911939) at util/main-loop.c:258 #6 0x00000000009453f2 in main_loop_wait (nonblocking=0) at util/main-loop.c:517 #7 0x00000000005c76b4 in main_loop () at vl.c:1898 #8 0x00000000005ceb77 in main (argc=49, argv=0x7fff921182b8, envp=0x7fff92118448) at vl.c:4709 > Migration is running in a background thread, so shouldn't be impacting the > main thread which handles VNC, unless the block layer is perhaps acquiring > the global qemu lock ? I wouldn't expect such a lock to be held for just > the bdrv_is_allocated call though. > > Regards, > Daniel > -- > |: http://berrange.com -o- http://www.flickr.com/photos/dberrange/ :| > |: http://libvirt.org -o- http://virt-manager.org :| > |: http://entangle-photo.org -o- http://search.cpan.org/~danberr/ :|
On Wed, Apr 5, 2017 at 6:44 PM, 858585 jemmy <jemmy858585@gmail.com> wrote: > On Wed, Apr 5, 2017 at 5:34 PM, Daniel P. Berrange <berrange@redhat.com> wrote: >> On Wed, Apr 05, 2017 at 05:27:58PM +0800, jemmy858585@gmail.com wrote: >>> From: Lidong Chen <lidongchen@tencent.com> >>> >>> when migration with high speed, mig_save_device_bulk invoke >>> bdrv_is_allocated too frequently, and cause vnc reponse slowly. >>> this patch limit the time used for bdrv_is_allocated. >> >> Can you explain why calling bdrv_is_allocated is impacting VNC performance ? >> > > bdrv_is_allocated is called after qemu_mutex_lock_iothread. > > if (bmds->shared_base) { > qemu_mutex_lock_iothread(); > aio_context_acquire(blk_get_aio_context(bb)); > /* Skip unallocated sectors; intentionally treats failure as > * an allocated sector */ > while (cur_sector < total_sectors && > !bdrv_is_allocated(blk_bs(bb), cur_sector, > MAX_IS_ALLOCATED_SEARCH, &nr_sectors)) { > cur_sector += nr_sectors; > } > aio_context_release(blk_get_aio_context(bb)); > qemu_mutex_unlock_iothread(); > } > > and the main thread is also call qemu_mutex_lock_iothread. > > #0 0x00007f107322f264 in __lll_lock_wait () from /lib64/libpthread.so.0 > #1 0x00007f107322a508 in _L_lock_854 () from /lib64/libpthread.so.0 > #2 0x00007f107322a3d7 in pthread_mutex_lock () from /lib64/libpthread.so.0 > #3 0x0000000000949ecb in qemu_mutex_lock (mutex=0xfc51a0) at > util/qemu-thread-posix.c:60 > #4 0x0000000000459e58 in qemu_mutex_lock_iothread () at /root/qemu/cpus.c:1516 > #5 0x0000000000945322 in os_host_main_loop_wait (timeout=28911939) at > util/main-loop.c:258 > #6 0x00000000009453f2 in main_loop_wait (nonblocking=0) at util/main-loop.c:517 > #7 0x00000000005c76b4 in main_loop () at vl.c:1898 > #8 0x00000000005ceb77 in main (argc=49, argv=0x7fff921182b8, > envp=0x7fff92118448) at vl.c:4709 > >> Migration is running in a background thread, so shouldn't be impacting the >> main thread which handles VNC, unless the block layer is perhaps acquiring >> the global qemu lock ? I wouldn't expect such a lock to be held for just >> the bdrv_is_allocated call though. >> I'm not sure it's safe to remove qemu_mutex_lock_iothread. i will analyze and test it later. this patch is simple, and can solve the problem now. >> Regards, >> Daniel >> -- >> |: http://berrange.com -o- http://www.flickr.com/photos/dberrange/ :| >> |: http://libvirt.org -o- http://virt-manager.org :| >> |: http://entangle-photo.org -o- http://search.cpan.org/~danberr/ :|
On Wed, Apr 05, 2017 at 05:27:58PM +0800, jemmy858585@gmail.com wrote: > From: Lidong Chen <lidongchen@tencent.com> > > when migration with high speed, mig_save_device_bulk invoke > bdrv_is_allocated too frequently, and cause vnc reponse slowly. > this patch limit the time used for bdrv_is_allocated. bdrv_is_allocated() is supposed to yield back to the event loop if it needs to block. If your VNC session is experiencing jitter then it's probably because a system call in the bdrv_is_allocated() code path is synchronous when it should be asynchronous. You could try to identify the system call using strace -f -T. In the output you'll see the duration of each system call. I guess there is a file I/O system call that is taking noticable amounts of time. A proper solution is to refactor the synchronous code to make it asynchronous. This might require invoking the system call from a thread pool worker. Stefan
On Thu, Apr 6, 2017 at 10:02 PM, Stefan Hajnoczi <stefanha@redhat.com> wrote: > On Wed, Apr 05, 2017 at 05:27:58PM +0800, jemmy858585@gmail.com wrote: >> From: Lidong Chen <lidongchen@tencent.com> >> >> when migration with high speed, mig_save_device_bulk invoke >> bdrv_is_allocated too frequently, and cause vnc reponse slowly. >> this patch limit the time used for bdrv_is_allocated. > > bdrv_is_allocated() is supposed to yield back to the event loop if it > needs to block. If your VNC session is experiencing jitter then it's > probably because a system call in the bdrv_is_allocated() code path is > synchronous when it should be asynchronous. > > You could try to identify the system call using strace -f -T. In the > output you'll see the duration of each system call. I guess there is a > file I/O system call that is taking noticable amounts of time. yes, i find the reason where bdrv_is_allocated needs to block. the mainly reason is caused by qemu_co_mutex_lock invoked by qcow2_co_get_block_status. qemu_co_mutex_lock(&s->lock); ret = qcow2_get_cluster_offset(bs, sector_num << 9, &bytes, &cluster_offset); qemu_co_mutex_unlock(&s->lock); other reason is caused by l2_load invoked by qcow2_get_cluster_offset. /* load the l2 table in memory */ ret = l2_load(bs, l2_offset, &l2_table); if (ret < 0) { return ret; } > > A proper solution is to refactor the synchronous code to make it > asynchronous. This might require invoking the system call from a > thread pool worker. > yes, i agree with you, but this is a big change. I will try to find how to optimize this code, maybe need a long time. this patch is not a perfect solution, but can alleviate the problem. > Stefan
On Fri, Apr 7, 2017 at 9:30 AM, 858585 jemmy <jemmy858585@gmail.com> wrote: > On Thu, Apr 6, 2017 at 10:02 PM, Stefan Hajnoczi <stefanha@redhat.com> wrote: >> On Wed, Apr 05, 2017 at 05:27:58PM +0800, jemmy858585@gmail.com wrote: >>> From: Lidong Chen <lidongchen@tencent.com> >>> >>> when migration with high speed, mig_save_device_bulk invoke >>> bdrv_is_allocated too frequently, and cause vnc reponse slowly. >>> this patch limit the time used for bdrv_is_allocated. >> >> bdrv_is_allocated() is supposed to yield back to the event loop if it >> needs to block. If your VNC session is experiencing jitter then it's >> probably because a system call in the bdrv_is_allocated() code path is >> synchronous when it should be asynchronous. >> >> You could try to identify the system call using strace -f -T. In the >> output you'll see the duration of each system call. I guess there is a >> file I/O system call that is taking noticable amounts of time. > > yes, i find the reason where bdrv_is_allocated needs to block. > > the mainly reason is caused by qemu_co_mutex_lock invoked by > qcow2_co_get_block_status. > qemu_co_mutex_lock(&s->lock); > ret = qcow2_get_cluster_offset(bs, sector_num << 9, &bytes, > &cluster_offset); > qemu_co_mutex_unlock(&s->lock); > > other reason is caused by l2_load invoked by > qcow2_get_cluster_offset. > > /* load the l2 table in memory */ > > ret = l2_load(bs, l2_offset, &l2_table); > if (ret < 0) { > return ret; > } > >> >> A proper solution is to refactor the synchronous code to make it >> asynchronous. This might require invoking the system call from a >> thread pool worker. >> > > yes, i agree with you, but this is a big change. > I will try to find how to optimize this code, maybe need a long time. > > this patch is not a perfect solution, but can alleviate the problem. Hi everyone: Do you think should we use this patch currently? and optimize this code later? Thanks. > >> Stefan
On Fri, Apr 07, 2017 at 09:30:33AM +0800, 858585 jemmy wrote: > On Thu, Apr 6, 2017 at 10:02 PM, Stefan Hajnoczi <stefanha@redhat.com> wrote: > > On Wed, Apr 05, 2017 at 05:27:58PM +0800, jemmy858585@gmail.com wrote: > > > > A proper solution is to refactor the synchronous code to make it > > asynchronous. This might require invoking the system call from a > > thread pool worker. > > > > yes, i agree with you, but this is a big change. > I will try to find how to optimize this code, maybe need a long time. > > this patch is not a perfect solution, but can alleviate the problem. Let's try to understand the problem fully first. Stefan
On Fri, Apr 7, 2017 at 7:34 PM, Stefan Hajnoczi <stefanha@redhat.com> wrote: > On Fri, Apr 07, 2017 at 09:30:33AM +0800, 858585 jemmy wrote: >> On Thu, Apr 6, 2017 at 10:02 PM, Stefan Hajnoczi <stefanha@redhat.com> wrote: >> > On Wed, Apr 05, 2017 at 05:27:58PM +0800, jemmy858585@gmail.com wrote: >> > >> > A proper solution is to refactor the synchronous code to make it >> > asynchronous. This might require invoking the system call from a >> > thread pool worker. >> > >> >> yes, i agree with you, but this is a big change. >> I will try to find how to optimize this code, maybe need a long time. >> >> this patch is not a perfect solution, but can alleviate the problem. > > Let's try to understand the problem fully first. > when migrate the vm with high speed, i find vnc response slowly sometime. not only vnc response slowly, virsh console aslo response slowly sometime. and the guest os block io performance is also reduce. the bug can be reproduce by this command: virsh migrate-setspeed 165cf436-312f-47e7-90f2-f8aa63f34893 900 virsh migrate --live 165cf436-312f-47e7-90f2-f8aa63f34893 --copy-storage-inc qemu+ssh://10.59.163.38/system and --copy-storage-all have no problem. virsh migrate --live 165cf436-312f-47e7-90f2-f8aa63f34893 --copy-storage-all qemu+ssh://10.59.163.38/system compare the difference between --copy-storage-inc and --copy-storage-all. i find out the reason is mig_save_device_bulk invoke bdrv_is_allocated, but bdrv_is_allocated is synchronous and maybe wait for a long time. i write this code to measure the time used by brdrv_is_allocated() 279 static int max_time = 0; 280 int tmp; 288 clock_gettime(CLOCK_MONOTONIC_RAW, &ts1); 289 ret = bdrv_is_allocated(blk_bs(bb), cur_sector, 290 MAX_IS_ALLOCATED_SEARCH, &nr_sectors); 291 clock_gettime(CLOCK_MONOTONIC_RAW, &ts2); 292 293 294 tmp = (ts2.tv_sec - ts1.tv_sec)*1000000000L 295 + (ts2.tv_nsec - ts1.tv_nsec); 296 if (tmp > max_time) { 297 max_time=tmp; 298 fprintf(stderr, "max_time is %d\n", max_time); 299 } the test result is below: max_time is 37014 max_time is 1075534 max_time is 17180913 max_time is 28586762 max_time is 49563584 max_time is 103085447 max_time is 110836833 max_time is 120331438 bdrv_is_allocated is called after qemu_mutex_lock_iothread. and the main thread is also call qemu_mutex_lock_iothread. so cause the main thread maybe wait for a long time. if (bmds->shared_base) { qemu_mutex_lock_iothread(); aio_context_acquire(blk_get_aio_context(bb)); /* Skip unallocated sectors; intentionally treats failure as * an allocated sector */ while (cur_sector < total_sectors && !bdrv_is_allocated(blk_bs(bb), cur_sector, MAX_IS_ALLOCATED_SEARCH, &nr_sectors)) { cur_sector += nr_sectors; } aio_context_release(blk_get_aio_context(bb)); qemu_mutex_unlock_iothread(); } #0 0x00007f107322f264 in __lll_lock_wait () from /lib64/libpthread.so.0 #1 0x00007f107322a508 in _L_lock_854 () from /lib64/libpthread.so.0 #2 0x00007f107322a3d7 in pthread_mutex_lock () from /lib64/libpthread.so.0 #3 0x0000000000949ecb in qemu_mutex_lock (mutex=0xfc51a0) at util/qemu-thread-posix.c:60 #4 0x0000000000459e58 in qemu_mutex_lock_iothread () at /root/qemu/cpus.c:1516 #5 0x0000000000945322 in os_host_main_loop_wait (timeout=28911939) at util/main-loop.c:258 #6 0x00000000009453f2 in main_loop_wait (nonblocking=0) at util/main-loop.c:517 #7 0x00000000005c76b4 in main_loop () at vl.c:1898 #8 0x00000000005ceb77 in main (argc=49, argv=0x7fff921182b8, envp=0x7fff92118448) at vl.c:4709 > Stefan
diff --git a/migration/block.c b/migration/block.c index 7734ff7..dbce931 100644 --- a/migration/block.c +++ b/migration/block.c @@ -39,6 +39,7 @@ #define MAX_IS_ALLOCATED_SEARCH 65536 #define MAX_INFLIGHT_IO 512 +#define BIG_DELAY 500000 //#define DEBUG_BLK_MIGRATION @@ -110,6 +111,7 @@ typedef struct BlkMigState { int transferred; int prev_progress; int bulk_completed; + int64_t time_ns_used; /* Lock must be taken _inside_ the iothread lock and any AioContexts. */ QemuMutex lock; @@ -272,16 +274,32 @@ static int mig_save_device_bulk(QEMUFile *f, BlkMigDevState *bmds) BlockBackend *bb = bmds->blk; BlkMigBlock *blk; int nr_sectors; + uint64_t ts1, ts2; + int ret = 0; + bool timeout_flag = false; if (bmds->shared_base) { qemu_mutex_lock_iothread(); aio_context_acquire(blk_get_aio_context(bb)); /* Skip unallocated sectors; intentionally treats failure as * an allocated sector */ - while (cur_sector < total_sectors && - !bdrv_is_allocated(blk_bs(bb), cur_sector, - MAX_IS_ALLOCATED_SEARCH, &nr_sectors)) { - cur_sector += nr_sectors; + while (cur_sector < total_sectors) { + ts1 = qemu_clock_get_ns(QEMU_CLOCK_REALTIME); + ret = bdrv_is_allocated(blk_bs(bb), cur_sector, + MAX_IS_ALLOCATED_SEARCH, &nr_sectors); + ts2 = qemu_clock_get_ns(QEMU_CLOCK_REALTIME); + + block_mig_state.time_ns_used += ts2 - ts1; + + if (!ret) { + cur_sector += nr_sectors; + if (block_mig_state.time_ns_used > BIG_DELAY) { + timeout_flag = true; + break; + } + } else { + break; + } } aio_context_release(blk_get_aio_context(bb)); qemu_mutex_unlock_iothread(); @@ -292,6 +310,11 @@ static int mig_save_device_bulk(QEMUFile *f, BlkMigDevState *bmds) return 1; } + if (timeout_flag) { + bmds->cur_sector = bmds->completed_sectors = cur_sector; + return 0; + } + bmds->completed_sectors = cur_sector; cur_sector &= ~((int64_t)BDRV_SECTORS_PER_DIRTY_CHUNK - 1); @@ -756,6 +779,7 @@ static int block_save_iterate(QEMUFile *f, void *opaque) } blk_mig_reset_dirty_cursor(); + block_mig_state.time_ns_used = 0; /* control the rate of transfer */ blk_mig_lock(); @@ -764,7 +788,8 @@ static int block_save_iterate(QEMUFile *f, void *opaque) qemu_file_get_rate_limit(f) && (block_mig_state.submitted + block_mig_state.read_done) < - MAX_INFLIGHT_IO) { + MAX_INFLIGHT_IO && + block_mig_state.time_ns_used <= BIG_DELAY) { blk_mig_unlock(); if (block_mig_state.bulk_completed == 0) { /* first finish the bulk phase */