Actions
Bug #6494
closedHigh memory consumption of qemu/librbd with enabled cache
% Done:
0%
Source:
other
Tags:
lin
Backport:
firefly, dumpling
Regression:
Severity:
2 - major
Reviewed:
Affected Versions:
ceph-qa-suite:
Pull request ID:
Crash signature (v1):
Crash signature (v2):
Description
I observe very high memory consumption on client with write-intensive load with qemu 1.6.0 + librbd 0.67.3.
For benchmarking purposes I'm trying to simultaneously run 15 VMs with 3 GiB of RAM on the one host. Each VM uses RBD image cloned from protected snapshot of "master image". After boot of each VM, "rpm -ihv" with a bunch of really large RPMs (~8 GiB of unpacked small files) is automatically started. Here is part of libvirt's XML of one of these VMs:
<disk type='network' device='disk'>
<driver name='qemu' type='raw' cache='writeback'/>
<source protocol='rbd' name='storage-benchmark-vms/vm-image-1:rbd_cache=1:rbd_cache_max_dirty=134217728:rbd_cache_size=268435456:rbd_cache_max_dirty_age=20'>
<host name='192.168.0.1' port='6789'/>
<host name='192.168.0.2' port='6789'/>
<host name='192.168.0.3' port='6789'/>
</source>
<target dev='hda' bus='ide'/>
<address type='drive' controller='0' bus='0' target='0' unit='0'/>
</disk>
Some time after start I can see unexpected growth of memory consumption of qemu-kvm processes:
5565 qemu 20 0 9091m 7.3g 10m S 2.6 7.7 4:41.31 qemu-kvm 5416 qemu 20 0 8059m 6.4g 10m S 27.8 6.8 4:40.93 qemu-kvm 5490 qemu 20 0 6723m 5.3g 10m S 26.2 5.6 4:30.51 qemu-kvm 5591 qemu 20 0 6475m 5.1g 10m S 39.1 5.3 4:35.68 qemu-kvm 5390 qemu 20 0 6227m 4.9g 10m S 2.0 5.1 4:26.42 qemu-kvm 5615 qemu 20 0 6203m 4.8g 10m S 27.5 5.1 4:34.56 qemu-kvm 5692 qemu 20 0 6171m 4.8g 10m S 17.5 5.1 4:28.95 qemu-kvm 5666 qemu 20 0 6163m 4.8g 10m S 2.0 5.1 4:29.66 qemu-kvm 5740 qemu 20 0 6139m 4.8g 10m S 23.2 5.1 4:39.22 qemu-kvm 5716 qemu 20 0 5899m 4.6g 10m S 20.2 4.8 4:30.84 qemu-kvm 5539 qemu 20 0 5827m 4.5g 10m S 1.7 4.8 4:27.02 qemu-kvm 5515 qemu 20 0 5651m 4.4g 10m S 4.6 4.7 4:25.20 qemu-kvm 5640 qemu 20 0 5603m 4.3g 10m S 6.6 4.6 4:28.90 qemu-kvm 5442 qemu 20 0 5373m 4.1g 10m S 2.3 4.4 4:28.45 qemu-kvm 5466 qemu 20 0 5387m 4.1g 10m S 41.7 4.3 4:41.00 qemu-kvm
It could grow up further:
5565 qemu 20 0 22.6g 18g 2772 S 2.6 20.0 6:07.40 qemu-kvm
And then free some part of memory at some point:
5565 qemu 20 0 8011m 6.0g 2796 S 2.3 6.3 6:23.10 qemu-kvm
I tried to reduce cache size to defaults, as suggested on #ceph (replace "rbd_cache=1:rbd_cache_max_dirty=134217728:rbd_cache_size=268435456:rbd_cache_max_dirty_age=20" with just "rbd_cache=1"), but it didn't help much:
15297 qemu 20 0 7747m 6.1g 10m S 1.0 6.4 4:47.26 qemu-kvm
Then I tried to disable cache (remove "cache='writeback'" and change rbd_cache to 0), and memory consumption became normal:
19590 qemu 20 0 4251m 3.0g 10m S 9.2 3.2 3:33.42 qemu-kvm 19526 qemu 20 0 4251m 3.0g 10m S 8.6 3.1 3:22.01 qemu-kvm 19399 qemu 20 0 4251m 3.0g 10m S 9.6 3.1 3:15.01 qemu-kvm 19612 qemu 20 0 4251m 3.0g 10m S 3.0 3.1 4:12.41 qemu-kvm 19568 qemu 20 0 4251m 3.0g 10m S 3.0 3.1 3:32.04 qemu-kvm 19632 qemu 20 0 4251m 3.0g 10m S 7.3 3.1 3:47.57 qemu-kvm 19419 qemu 20 0 4251m 3.0g 10m S 8.9 3.1 3:20.40 qemu-kvm 19484 qemu 20 0 4251m 3.0g 10m S 7.6 3.1 3:30.56 qemu-kvm 19676 qemu 20 0 4251m 3.0g 10m S 4.0 3.1 3:48.99 qemu-kvm 19654 qemu 20 0 4251m 3.0g 10m S 7.3 3.1 3:49.83 qemu-kvm 19464 qemu 20 0 4251m 3.0g 10m S 8.9 3.1 3:45.45 qemu-kvm 19441 qemu 20 0 4251m 3.0g 10m S 7.3 3.1 3:20.58 qemu-kvm 19377 qemu 20 0 4251m 3.0g 10m S 7.9 3.1 3:16.99 qemu-kvm 19548 qemu 20 0 4251m 3.0g 10m S 9.9 3.1 3:33.59 qemu-kvm 19506 qemu 20 0 4251m 3.0g 10m S 7.6 3.1 3:16.94 qemu-kvm
I also tried to drop all caches inside one of the VMs and see how memory usage of qemu-kvm will change:
killall -s STOP rpm sync echo 3 >/proc/sys/vm/drop_caches
But it didn't made any difference outside of VM (except CPU usage because of SIGSTOP).
Files
Updated by Ivan Mironov over 10 years ago
- File massif.out.8867 massif.out.8867 added
It seems that I found a way to run qemu-kvm under valgrind/massif and trigger this issue. It looks like all this happens only if VM is able to generate write requests much faster that network can transmit. I only have 1 gbit/s network on my test setup, but it is still too fast for just one qemu running under valgrind, so I manually reduced network bandwidth with "tc". Here is the result:
--------------------------------------------------------------------------------
Command: /usr/libexec/qemu-kvm -name storage-benchmark-vm-1 -M pc-i440fx-1.6
-enable-kvm -m 3072 -smp 2,sockets=2,cores=1,threads=1 -uuid ec7d60dc-423b-db56-1e83-9781200b13b4
-no-user-config -nodefaults -rtc base=utc -no-hpet -boot c
-drive file=rbd:storage-benchmark-vms/vm-image-3:rbd_cache=1:auth_supported=none:mon_host=192.168.0.1\:6789;192.168.0.2\:6789;192.168.0.3\:6789,if=none,id=drive-ide0-0-0,format=raw,cache=writeback
-device ide-drive,bus=ide.0,unit=0,drive=drive-ide0-0-0,id=ide0-0-0
-drive file=/oneclickse/test//tests/current.iso,if=none,media=cdrom,id=drive-ide0-1-0,readonly=on,format=raw,cache=none
-device ide-drive,bus=ide.1,unit=0,drive=drive-ide0-1-0,id=ide0-1-0 -usb -vnc 0.0.0.0:51 -vga cirrus
-device virtio-balloon-pci,id=balloon0,bus=pci.0,addr=0x3
Massif arguments: --alloc-fn=g_malloc --alloc-fn=g_malloc0
ms_print arguments: massif.out.8867
--------------------------------------------------------------------------------
GB
5.274^ #
| #
| #
| #
| @@# :
| @ # :
| @ # @@:
| @ # @ :
| @ # @ :
| @ # :@ :
| @@@ # :@ :
| @ @ # :@ :
| @ @ # ::@ :
| @@ @ # : ::@ :
| @@ @ # : ::@ :
| @@ @ # : @ :::@ :
| :@@ @ #:::: @ :::@ :
| @ :@@ @ #: ::@:: @ :::@ :
| @ :@@ @ #: ::@: :@::::@ :
| @ @ :: :@@ @ #: ::@: ::@::::@ ::
0 +----------------------------------------------------------------------->Gi
0 274.1
Number of snapshots: 58
Detailed snapshots: [4, 9, 21, 24, 26, 27, 28, 29, 30 (peak), 34, 38, 43, 48, 57]
--------------------------------------------------------------------------------
n time(i) total(B) useful-heap(B) extra-heap(B) stacks(B)
--------------------------------------------------------------------------------
0 0 0 0 0 0
1 5,607,065,627 11,631,800 11,235,363 396,437 0
2 11,972,275,041 20,512,312 19,579,568 932,744 0
3 16,330,249,323 37,424,608 37,094,162 330,446 0
4 20,553,079,730 478,834,640 477,854,067 980,573 0
99.80% (477,854,067B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc.
->81.05% (388,097,673B) 0x7C20D8D: ceph::buffer::create(unsigned int) (buffer.cc:196)
| ->80.59% (385,875,968B) 0x7C20E63: ceph::buffer::ptr::ptr(unsigned int) (buffer.cc:261)
| | ->78.83% (377,487,360B) 0x769612A: Striper::StripedReadResult::assemble_result(CephContext*, ceph::buffer::list&, bool) (Striper.cc:326)
| | | ->78.83% (377,487,360B) 0x7642DA4: librbd::AioCompletion::finalize(CephContext*, long) (AioCompletion.cc:41)
| | | ->78.83% (377,487,360B) 0x7643515: librbd::AioCompletion::complete_request(CephContext*, long) (AioCompletion.cc:72)
| | | ->78.83% (377,487,360B) 0x7643C7F: librbd::C_AioRead::finish(int) (AioCompletion.cc:98)
| | | ->78.83% (377,487,360B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | ->78.83% (377,487,360B) 0x7642C2F: librbd::C_CacheRead::finish(int) (AioRequest.h:40)
| | | ->78.83% (377,487,360B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | ->78.83% (377,487,360B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | ->78.83% (377,487,360B) 0x76924D3: finish_contexts(CephContext*, std::list<Context*, std::allocator<Context*> >&, int) (Context.h:98)
| | | ->78.83% (377,487,360B) 0x768BC69: ObjectCacher::bh_read_finish(long, sobject_t, unsigned long, long, unsigned long, ceph::buffer::list&, int, bool) (ObjectCacher.cc:794)
| | | ->78.83% (377,487,360B) 0x76956E5: ObjectCacher::C_ReadFinish::finish(int) (ObjectCacher.h:489)
| | | ->78.83% (377,487,360B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | ->78.83% (377,487,360B) 0x76796F6: librbd::C_Request::finish(int) (LibrbdWriteback.cc:55)
| | | ->78.83% (377,487,360B) 0x7676DC2: librbd::context_cb(void*, void*) (LibrbdWriteback.cc:35)
| | | ->78.83% (377,487,360B) 0x7A51F96: librados::C_AioComplete::finish(int) (AioCompletionImpl.h:175)
| | | ->78.83% (377,487,360B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | ->78.83% (377,487,360B) 0x7ABD616: Finisher::finisher_thread_entry() (Finisher.cc:56)
| | | ->78.83% (377,487,360B) 0x674884F: start_thread (in /lib64/libpthread-2.12.so)
| | | ->78.83% (377,487,360B) 0xB4CF90B: clone (in /lib64/libc-2.12.so)
| | |
| | ->01.75% (8,388,608B) 0x768B832: ObjectCacher::bh_read_finish(long, sobject_t, unsigned long, long, unsigned long, ceph::buffer::list&, int, bool) (ObjectCacher.cc:642)
| | | ->01.75% (8,388,608B) 0x76956E5: ObjectCacher::C_ReadFinish::finish(int) (ObjectCacher.h:489)
| | | ->01.75% (8,388,608B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | ->01.75% (8,388,608B) 0x76796F6: librbd::C_Request::finish(int) (LibrbdWriteback.cc:55)
| | | ->01.75% (8,388,608B) 0x7676DC2: librbd::context_cb(void*, void*) (LibrbdWriteback.cc:35)
| | | ->01.75% (8,388,608B) 0x7A51F96: librados::C_AioComplete::finish(int) (AioCompletionImpl.h:175)
| | | ->01.75% (8,388,608B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | ->01.75% (8,388,608B) 0x7ABD616: Finisher::finisher_thread_entry() (Finisher.cc:56)
| | | ->01.75% (8,388,608B) 0x674884F: start_thread (in /lib64/libpthread-2.12.so)
| | | ->01.75% (8,388,608B) 0xB4CF90B: clone (in /lib64/libc-2.12.so)
| | |
| | ->00.00% (0B) in 1+ places, all below ms_print's threshold (01.00%)
| |
| ->00.46% (2,221,705B) in 1+ places, all below ms_print's threshold (01.00%)
|
->11.63% (55,685,120B) 0x7C207E8: ceph::buffer::create_page_aligned(unsigned int) (buffer.cc:142)
| ->11.63% (55,685,120B) 0x7BA4EAB: Pipe::read_message(Message**) (Pipe.cc:1664)
| | ->11.63% (55,685,120B) 0x7BB39CF: Pipe::reader() (Pipe.cc:1399)
| | ->11.63% (55,685,120B) 0x7BB6C0B: Pipe::Reader::entry() (Pipe.h:47)
| | ->11.63% (55,685,120B) 0x674884F: start_thread (in /lib64/libpthread-2.12.so)
| | ->11.63% (55,685,120B) 0xB4CF90B: clone (in /lib64/libc-2.12.so)
| |
| ->00.00% (0B) in 1+ places, all below ms_print's threshold (01.00%)
|
->01.79% (8,565,106B) in 314 places, all below massif's threshold (01.00%)
--------------------------------------------------------------------------------
n time(i) total(B) useful-heap(B) extra-heap(B) stacks(B)
--------------------------------------------------------------------------------
5 26,599,009,471 122,125,400 121,007,944 1,117,456 0
6 31,961,814,888 225,807,288 225,412,549 394,739 0
7 39,207,023,695 112,298,376 111,784,451 513,925 0
8 45,540,155,093 82,709,568 82,402,864 306,704 0
9 49,492,310,845 115,651,216 115,294,790 356,426 0
99.69% (115,294,790B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc.
->28.99% (33,529,856B) 0x7C207E8: ceph::buffer::create_page_aligned(unsigned int) (buffer.cc:142)
| ->28.99% (33,529,856B) 0x7BA4EAB: Pipe::read_message(Message**) (Pipe.cc:1664)
| | ->28.99% (33,529,856B) 0x7BB39CF: Pipe::reader() (Pipe.cc:1399)
| | ->28.99% (33,529,856B) 0x7BB6C0B: Pipe::Reader::entry() (Pipe.h:47)
| | ->28.99% (33,529,856B) 0x674884F: start_thread (in /lib64/libpthread-2.12.so)
| | ->28.99% (33,529,856B) 0xB4CF90B: clone (in /lib64/libc-2.12.so)
| |
| ->00.00% (0B) in 1+ places, all below ms_print's threshold (01.00%)
|
->14.53% (16,801,792B) 0x7C20D8D: ceph::buffer::create(unsigned int) (buffer.cc:196)
| ->14.51% (16,777,216B) 0x7C20E63: ceph::buffer::ptr::ptr(unsigned int) (buffer.cc:261)
| | ->14.51% (16,777,216B) 0x769612A: Striper::StripedReadResult::assemble_result(CephContext*, ceph::buffer::list&, bool) (Striper.cc:326)
| | | ->14.51% (16,777,216B) 0x7642DA4: librbd::AioCompletion::finalize(CephContext*, long) (AioCompletion.cc:41)
| | | ->07.25% (8,388,608B) 0x7643515: librbd::AioCompletion::complete_request(CephContext*, long) (AioCompletion.cc:72)
| | | | ->07.25% (8,388,608B) 0x7643C7F: librbd::C_AioRead::finish(int) (AioCompletion.cc:98)
| | | | ->07.25% (8,388,608B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->07.25% (8,388,608B) 0x7642C2F: librbd::C_CacheRead::finish(int) (AioRequest.h:40)
| | | | ->07.25% (8,388,608B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->07.25% (8,388,608B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->07.25% (8,388,608B) 0x76924D3: finish_contexts(CephContext*, std::list<Context*, std::allocator<Context*> >&, int) (Context.h:98)
| | | | ->07.25% (8,388,608B) 0x768BC69: ObjectCacher::bh_read_finish(long, sobject_t, unsigned long, long, unsigned long, ceph::buffer::list&, int, bool) (ObjectCacher.cc:794)
| | | | ->07.25% (8,388,608B) 0x76956E5: ObjectCacher::C_ReadFinish::finish(int) (ObjectCacher.h:489)
| | | | ->07.25% (8,388,608B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->07.25% (8,388,608B) 0x76796F6: librbd::C_Request::finish(int) (LibrbdWriteback.cc:55)
| | | | ->07.25% (8,388,608B) 0x7676DC2: librbd::context_cb(void*, void*) (LibrbdWriteback.cc:35)
| | | | ->07.25% (8,388,608B) 0x7A51F96: librados::C_AioComplete::finish(int) (AioCompletionImpl.h:175)
| | | | ->07.25% (8,388,608B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->07.25% (8,388,608B) 0x7ABD616: Finisher::finisher_thread_entry() (Finisher.cc:56)
| | | | ->07.25% (8,388,608B) 0x674884F: start_thread (in /lib64/libpthread-2.12.so)
| | | | ->07.25% (8,388,608B) 0xB4CF90B: clone (in /lib64/libc-2.12.so)
| | | |
| | | ->07.25% (8,388,608B) 0x7644418: librbd::AioCompletion::finish_adding_requests(CephContext*) (AioCompletion.cc:27)
| | | ->07.25% (8,388,608B) 0x766BBDE: librbd::aio_read(librbd::ImageCtx*, std::vector<std::pair<unsigned long, unsigned long>, std::allocator<std::pair<unsigned long, unsigned long> > > const&, char*, ceph::buffer::list*, librbd::AioCompletion*) (internal.cc:3102)
| | | ->07.25% (8,388,608B) 0x7645D54: librbd::AioRequest::read_from_parent(std::vector<std::pair<unsigned long, unsigned long>, std::allocator<std::pair<unsigned long, unsigned long> > >&) (AioRequest.cc:52)
| | | ->07.25% (8,388,608B) 0x76468E8: librbd::AbstractWrite::should_complete(int) (AioRequest.cc:187)
| | | ->07.25% (8,388,608B) 0x7655581: librbd::rados_req_cb(void*, void*) (AioRequest.h:37)
| | | ->07.25% (8,388,608B) 0x7A51F16: librados::C_AioSafe::finish(int) (AioCompletionImpl.h:194)
| | | ->07.25% (8,388,608B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | ->07.25% (8,388,608B) 0x7ABD616: Finisher::finisher_thread_entry() (Finisher.cc:56)
| | | ->07.25% (8,388,608B) 0x674884F: start_thread (in /lib64/libpthread-2.12.so)
| | | ->07.25% (8,388,608B) 0xB4CF90B: clone (in /lib64/libc-2.12.so)
| | |
| | ->00.00% (0B) in 1+ places, all below ms_print's threshold (01.00%)
| |
| ->00.02% (24,576B) in 1+ places, all below ms_print's threshold (01.00%)
|
->02.72% (3,145,728B) 0xAEF1282: _pixman_bits_image_init (in /usr/lib64/libpixman-1.so.0.26.2)
| ->02.72% (3,145,728B) 0xAEF135A: pixman_image_create_bits (in /usr/lib64/libpixman-1.so.0.26.2)
| ->02.72% (3,145,728B) 0x355947: vnc_dpy_switch (vnc.c:585)
| | ->02.72% (3,145,728B) 0x3368C0: dpy_gfx_replace_surface (console.c:1424)
| | | ->02.72% (3,145,728B) 0x38E461: vga_update_display (vga.c:1699)
| | | | ->02.72% (3,145,728B) 0x3521EC: vnc_refresh (vnc.c:2741)
| | | | ->02.72% (3,145,728B) 0x335310: gui_update (console.c:1436)
| | | | ->02.72% (3,145,728B) 0x3173E9: qemu_run_timers (qemu-timer.c:394)
| | | | ->02.72% (3,145,728B) 0x31743B: qemu_run_all_timers (qemu-timer.c:453)
| | | | ->02.72% (3,145,728B) 0x2DC28B: main_loop_wait (main-loop.c:471)
| | | | ->02.72% (3,145,728B) 0x35B235: main (vl.c:2090)
| | | |
| | | ->00.00% (0B) in 1+ places, all below ms_print's threshold (01.00%)
| | |
| | ->00.00% (0B) in 1+ places, all below ms_print's threshold (01.00%)
| |
| ->00.00% (0B) in 1+ places, all below ms_print's threshold (01.00%)
|
->02.64% (3,052,816B) 0x358F3B: malloc_and_trace (vl.c:2830)
| ->02.16% (2,493,990B) 0x52767D1: g_malloc (in /lib64/libglib-2.0.so.0.2200.5)
| | ->01.81% (2,097,152B) 0x1E8C5D: qemu_coroutine_new (coroutine-ucontext.c:144)
| | | ->01.81% (2,097,152B) 0x31273F: qemu_coroutine_create (qemu-coroutine.c:44)
| | | ->01.81% (2,097,152B) in 2 places, all below massif's threshold (01.00%)
| | |
| | ->00.34% (396,838B) in 1+ places, all below ms_print's threshold (01.00%)
| |
| ->00.48% (558,826B) in 1+ places, all below ms_print's threshold (01.00%)
|
->01.87% (2,159,212B) in 312 places, all below massif's threshold (01.00%)
--------------------------------------------------------------------------------
n time(i) total(B) useful-heap(B) extra-heap(B) stacks(B)
--------------------------------------------------------------------------------
10 55,661,409,321 106,102,776 105,748,409 354,367 0
11 61,311,879,350 154,343,640 153,876,820 466,820 0
12 69,144,336,382 115,429,160 115,105,827 323,333 0
13 75,437,173,160 163,611,320 163,065,860 545,460 0
14 83,156,536,516 84,315,264 83,901,182 414,082 0
15 87,098,528,861 118,413,600 118,080,338 333,262 0
16 91,971,623,468 89,678,480 88,844,587 833,893 0
17 97,833,308,214 116,851,624 116,469,391 382,233 0
18 105,548,741,092 176,541,048 175,232,796 1,308,252 0
19 111,157,341,614 108,397,120 107,148,969 1,248,151 0
20 116,958,090,460 209,663,896 208,528,526 1,135,370 0
21 123,438,390,514 1,042,055,400 1,040,255,936 1,799,464 0
99.83% (1,040,255,936B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc.
->90.97% (947,978,377B) 0x7C20D8D: ceph::buffer::create(unsigned int) (buffer.cc:196)
| ->90.97% (947,912,704B) 0x7C20E63: ceph::buffer::ptr::ptr(unsigned int) (buffer.cc:261)
| | ->90.16% (939,524,096B) 0x769612A: Striper::StripedReadResult::assemble_result(CephContext*, ceph::buffer::list&, bool) (Striper.cc:326)
| | | ->90.16% (939,524,096B) 0x7642DA4: librbd::AioCompletion::finalize(CephContext*, long) (AioCompletion.cc:41)
| | | ->90.16% (939,524,096B) 0x7643515: librbd::AioCompletion::complete_request(CephContext*, long) (AioCompletion.cc:72)
| | | | ->90.16% (939,524,096B) 0x7643C7F: librbd::C_AioRead::finish(int) (AioCompletion.cc:98)
| | | | ->90.16% (939,524,096B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->90.16% (939,524,096B) 0x7642C2F: librbd::C_CacheRead::finish(int) (AioRequest.h:40)
| | | | ->90.16% (939,524,096B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->90.16% (939,524,096B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->90.16% (939,524,096B) 0x76924D3: finish_contexts(CephContext*, std::list<Context*, std::allocator<Context*> >&, int) (Context.h:98)
| | | | ->90.16% (939,524,096B) 0x768BC69: ObjectCacher::bh_read_finish(long, sobject_t, unsigned long, long, unsigned long, ceph::buffer::list&, int, bool) (ObjectCacher.cc:794)
| | | | ->90.16% (939,524,096B) 0x76956E5: ObjectCacher::C_ReadFinish::finish(int) (ObjectCacher.h:489)
| | | | ->90.16% (939,524,096B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->90.16% (939,524,096B) 0x76796F6: librbd::C_Request::finish(int) (LibrbdWriteback.cc:55)
| | | | ->90.16% (939,524,096B) 0x7676DC2: librbd::context_cb(void*, void*) (LibrbdWriteback.cc:35)
| | | | ->90.16% (939,524,096B) 0x7A51F96: librados::C_AioComplete::finish(int) (AioCompletionImpl.h:175)
| | | | ->90.16% (939,524,096B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->90.16% (939,524,096B) 0x7ABD616: Finisher::finisher_thread_entry() (Finisher.cc:56)
| | | | ->90.16% (939,524,096B) 0x674884F: start_thread (in /lib64/libpthread-2.12.so)
| | | | ->90.16% (939,524,096B) 0xB4CF90B: clone (in /lib64/libc-2.12.so)
| | | |
| | | ->00.00% (0B) in 1+ places, all below ms_print's threshold (01.00%)
| | |
| | ->00.81% (8,388,608B) in 1+ places, all below ms_print's threshold (01.00%)
| |
| ->00.01% (65,673B) in 1+ places, all below ms_print's threshold (01.00%)
|
->02.41% (25,128,960B) 0x7C207E8: ceph::buffer::create_page_aligned(unsigned int) (buffer.cc:142)
| ->02.41% (25,128,960B) 0x7BA4EAB: Pipe::read_message(Message**) (Pipe.cc:1664)
| | ->02.41% (25,128,960B) 0x7BB39CF: Pipe::reader() (Pipe.cc:1399)
| | ->02.41% (25,128,960B) 0x7BB6C0B: Pipe::Reader::entry() (Pipe.h:47)
| | ->02.41% (25,128,960B) 0x674884F: start_thread (in /lib64/libpthread-2.12.so)
| | ->02.41% (25,128,960B) 0xB4CF90B: clone (in /lib64/libc-2.12.so)
| |
| ->00.00% (0B) in 1+ places, all below ms_print's threshold (01.00%)
|
->00.84% (8,728,492B) in 1+ places, all below ms_print's threshold (01.00%)
--------------------------------------------------------------------------------
n time(i) total(B) useful-heap(B) extra-heap(B) stacks(B)
--------------------------------------------------------------------------------
22 129,271,052,719 112,145,360 110,360,672 1,784,688 0
23 134,287,876,761 291,533,584 288,859,969 2,673,615 0
24 142,673,615,936 79,889,872 79,260,793 629,079 0
99.21% (79,260,793B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc.
->31.49% (25,153,536B) 0x7C207E8: ceph::buffer::create_page_aligned(unsigned int) (buffer.cc:142)
| ->31.49% (25,153,536B) 0x7BA4EAB: Pipe::read_message(Message**) (Pipe.cc:1664)
| | ->31.49% (25,153,536B) 0x7BB39CF: Pipe::reader() (Pipe.cc:1399)
| | ->31.49% (25,153,536B) 0x7BB6C0B: Pipe::Reader::entry() (Pipe.h:47)
| | ->31.49% (25,153,536B) 0x674884F: start_thread (in /lib64/libpthread-2.12.so)
| | ->31.49% (25,153,536B) 0xB4CF90B: clone (in /lib64/libc-2.12.so)
| |
| ->00.00% (0B) in 1+ places, all below ms_print's threshold (01.00%)
|
->03.94% (3,145,728B) 0xAEF1282: _pixman_bits_image_init (in /usr/lib64/libpixman-1.so.0.26.2)
| ->03.94% (3,145,728B) 0xAEF135A: pixman_image_create_bits (in /usr/lib64/libpixman-1.so.0.26.2)
| ->03.94% (3,145,728B) 0x355947: vnc_dpy_switch (vnc.c:585)
| | ->03.94% (3,145,728B) 0x3368C0: dpy_gfx_replace_surface (console.c:1424)
| | | ->03.94% (3,145,728B) 0x38E461: vga_update_display (vga.c:1699)
| | | | ->03.94% (3,145,728B) 0x3521EC: vnc_refresh (vnc.c:2741)
| | | | ->03.94% (3,145,728B) 0x335310: gui_update (console.c:1436)
| | | | ->03.94% (3,145,728B) 0x3173E9: qemu_run_timers (qemu-timer.c:394)
| | | | ->03.94% (3,145,728B) 0x31743B: qemu_run_all_timers (qemu-timer.c:453)
| | | | ->03.94% (3,145,728B) 0x2DC28B: main_loop_wait (main-loop.c:471)
| | | | ->03.94% (3,145,728B) 0x35B235: main (vl.c:2090)
| | | |
| | | ->00.00% (0B) in 1+ places, all below ms_print's threshold (01.00%)
| | |
| | ->00.00% (0B) in 1+ places, all below ms_print's threshold (01.00%)
| |
| ->00.00% (0B) in 1+ places, all below ms_print's threshold (01.00%)
|
->03.82% (3,055,168B) 0x358F3B: malloc_and_trace (vl.c:2830)
| ->03.12% (2,496,342B) 0x52767D1: g_malloc (in /lib64/libglib-2.0.so.0.2200.5)
| | ->02.63% (2,097,152B) 0x1E8C5D: qemu_coroutine_new (coroutine-ucontext.c:144)
| | | ->02.63% (2,097,152B) 0x31273F: qemu_coroutine_create (qemu-coroutine.c:44)
| | | ->01.31% (1,048,576B) 0x1AF4AD: bdrv_rwv_co (block.c:2223)
| | | | ->01.31% (1,048,576B) 0x1AF5CF: bdrv_rw_co (block.c:2245)
| | | | ->01.31% (1,048,576B) 0x1AF892: bdrv_read_unthrottled (block.c:2264)
| | | | ->01.31% (1,048,576B) 0x21CA6E: guess_disk_lchs (hd-geometry.c:68)
| | | | ->01.31% (1,048,576B) 0x21CB9E: hd_geometry_guess (hd-geometry.c:125)
| | | | ->01.31% (1,048,576B) 0x2189D8: blkconf_geometry (block.c:41)
| | | | ->01.31% (1,048,576B) 0x26702F: ide_dev_initfn (qdev.c:164)
| | | | ->01.31% (1,048,576B) 0x236452: device_realize (qdev.c:178)
| | | | ->01.31% (1,048,576B) 0x236D11: device_set_realized (qdev.c:699)
| | | | ->01.31% (1,048,576B) 0x32328C: property_set_bool (object.c:1300)
| | | | ->01.31% (1,048,576B) 0x325E83: object_property_set_qobject (qom-qobject.c:24)
| | | | ->01.31% (1,048,576B) 0x323AAC: object_property_set_bool (object.c:851)
| | | | ->01.31% (1,048,576B) 0x237668: qdev_init (qdev.c:163)
| | | | ->01.31% (1,048,576B) 0x30A85E: qdev_device_add (qdev-monitor.c:527)
| | | | ->01.31% (1,048,576B) 0x357497: device_init_func (vl.c:2383)
| | | | ->01.31% (1,048,576B) 0x481818: qemu_opts_foreach (qemu-option.c:1143)
| | | | ->01.31% (1,048,576B) 0x35B0B6: main (vl.c:4334)
| | | |
| | | ->01.31% (1,048,576B) 0x1AB983: bdrv_co_aio_rw_vector (block.c:3893)
| | | ->01.31% (1,048,576B) 0x1ABB4F: bdrv_aio_readv (block.c:3377)
| | | ->01.31% (1,048,576B) 0x1EF433: dma_bdrv_cb (dma-helpers.c:172)
| | | ->01.31% (1,048,576B) 0x1EF55A: dma_bdrv_io (dma-helpers.c:218)
| | | ->01.31% (1,048,576B) 0x1EF61B: dma_bdrv_read (dma-helpers.c:227)
| | | ->01.31% (1,048,576B) 0x2641AB: ide_dma_cb (core.c:676)
| | | ->01.31% (1,048,576B) 0x265EC1: bmdma_cmd_writeb (pci.c:324)
| | | ->01.31% (1,048,576B) 0x3BB036: access_with_adjusted_size (memory.c:477)
| | | ->01.31% (1,048,576B) 0x3BC4EA: io_mem_write (memory.c:989)
| | | ->01.31% (1,048,576B) 0x36DEA5: address_space_rw (exec.c:1973)
| | | ->01.31% (1,048,576B) 0x3B7264: cpu_outb (ioport.c:51)
| | | ->01.31% (1,048,576B) 0x3BA7FF: kvm_cpu_exec (kvm-all.c:1517)
| | | ->01.31% (1,048,576B) 0x3651B0: qemu_kvm_cpu_thread_fn (cpus.c:785)
| | | ->01.31% (1,048,576B) 0x674884F: start_thread (in /lib64/libpthread-2.12.so)
| | | ->01.31% (1,048,576B) 0xB4CF90B: clone (in /lib64/libc-2.12.so)
| | |
| | ->00.50% (399,190B) in 1+ places, all below ms_print's threshold (01.00%)
| |
| ->00.70% (558,826B) in 1+ places, all below ms_print's threshold (01.00%)
|
->01.56% (1,246,065B) in 313 places, all below massif's threshold (01.00%)
|
->01.18% (943,616B) 0x358EF7: realloc_and_trace (vl.c:2837)
->01.18% (943,616B) 0x527661F: g_realloc (in /lib64/libglib-2.0.so.0.2200.5)
->01.18% (943,616B) in 11 places, all below massif's threshold (01.00%)
--------------------------------------------------------------------------------
n time(i) total(B) useful-heap(B) extra-heap(B) stacks(B)
--------------------------------------------------------------------------------
25 149,411,482,472 1,223,140,776 1,220,508,587 2,632,189 0
26 153,796,649,825 2,087,597,752 2,084,546,096 3,051,656 0
99.85% (2,084,546,096B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc.
->95.64% (1,996,521,472B) 0x7C20D8D: ceph::buffer::create(unsigned int) (buffer.cc:196)
| ->95.64% (1,996,488,704B) 0x7C20E63: ceph::buffer::ptr::ptr(unsigned int) (buffer.cc:261)
| | ->95.23% (1,988,100,096B) 0x769612A: Striper::StripedReadResult::assemble_result(CephContext*, ceph::buffer::list&, bool) (Striper.cc:326)
| | | ->95.23% (1,988,100,096B) 0x7642DA4: librbd::AioCompletion::finalize(CephContext*, long) (AioCompletion.cc:41)
| | | ->95.23% (1,988,100,096B) 0x7643515: librbd::AioCompletion::complete_request(CephContext*, long) (AioCompletion.cc:72)
| | | | ->95.23% (1,988,100,096B) 0x7643C7F: librbd::C_AioRead::finish(int) (AioCompletion.cc:98)
| | | | ->95.23% (1,988,100,096B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->95.23% (1,988,100,096B) 0x7642C2F: librbd::C_CacheRead::finish(int) (AioRequest.h:40)
| | | | ->95.23% (1,988,100,096B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->95.23% (1,988,100,096B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->95.23% (1,988,100,096B) 0x76924D3: finish_contexts(CephContext*, std::list<Context*, std::allocator<Context*> >&, int) (Context.h:98)
| | | | ->95.23% (1,988,100,096B) 0x768BC69: ObjectCacher::bh_read_finish(long, sobject_t, unsigned long, long, unsigned long, ceph::buffer::list&, int, bool) (ObjectCacher.cc:794)
| | | | ->95.23% (1,988,100,096B) 0x76956E5: ObjectCacher::C_ReadFinish::finish(int) (ObjectCacher.h:489)
| | | | ->95.23% (1,988,100,096B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->95.23% (1,988,100,096B) 0x76796F6: librbd::C_Request::finish(int) (LibrbdWriteback.cc:55)
| | | | ->95.23% (1,988,100,096B) 0x7676DC2: librbd::context_cb(void*, void*) (LibrbdWriteback.cc:35)
| | | | ->95.23% (1,988,100,096B) 0x7A51F96: librados::C_AioComplete::finish(int) (AioCompletionImpl.h:175)
| | | | ->95.23% (1,988,100,096B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->95.23% (1,988,100,096B) 0x7ABD616: Finisher::finisher_thread_entry() (Finisher.cc:56)
| | | | ->95.23% (1,988,100,096B) 0x674884F: start_thread (in /lib64/libpthread-2.12.so)
| | | | ->95.23% (1,988,100,096B) 0xB4CF90B: clone (in /lib64/libc-2.12.so)
| | | |
| | | ->00.00% (0B) in 1+ places, all below ms_print's threshold (01.00%)
| | |
| | ->00.40% (8,388,608B) in 1+ places, all below ms_print's threshold (01.00%)
| |
| ->00.00% (32,768B) in 1+ places, all below ms_print's threshold (01.00%)
|
->01.20% (25,153,536B) 0x7C207E8: ceph::buffer::create_page_aligned(unsigned int) (buffer.cc:142)
| ->01.20% (25,153,536B) 0x7BA4EAB: Pipe::read_message(Message**) (Pipe.cc:1664)
| | ->01.20% (25,153,536B) 0x7BB39CF: Pipe::reader() (Pipe.cc:1399)
| | ->01.20% (25,153,536B) 0x7BB6C0B: Pipe::Reader::entry() (Pipe.h:47)
| | ->01.20% (25,153,536B) 0x674884F: start_thread (in /lib64/libpthread-2.12.so)
| | ->01.20% (25,153,536B) 0xB4CF90B: clone (in /lib64/libc-2.12.so)
| |
| ->00.00% (0B) in 1+ places, all below ms_print's threshold (01.00%)
|
->00.47% (9,734,623B) in 1+ places, all below ms_print's threshold (01.00%)
--------------------------------------------------------------------------------
n time(i) total(B) useful-heap(B) extra-heap(B) stacks(B)
--------------------------------------------------------------------------------
27 158,522,635,188 3,010,805,008 3,007,303,477 3,501,531 0
99.88% (3,007,303,477B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc.
->96.96% (2,919,268,352B) 0x7C20D8D: ceph::buffer::create(unsigned int) (buffer.cc:196)
| ->96.96% (2,919,235,584B) 0x7C20E63: ceph::buffer::ptr::ptr(unsigned int) (buffer.cc:261)
| | ->96.68% (2,910,846,976B) 0x769612A: Striper::StripedReadResult::assemble_result(CephContext*, ceph::buffer::list&, bool) (Striper.cc:326)
| | | ->96.68% (2,910,846,976B) 0x7642DA4: librbd::AioCompletion::finalize(CephContext*, long) (AioCompletion.cc:41)
| | | ->96.68% (2,910,846,976B) 0x7643515: librbd::AioCompletion::complete_request(CephContext*, long) (AioCompletion.cc:72)
| | | | ->96.68% (2,910,846,976B) 0x7643C7F: librbd::C_AioRead::finish(int) (AioCompletion.cc:98)
| | | | ->96.68% (2,910,846,976B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->96.68% (2,910,846,976B) 0x7642C2F: librbd::C_CacheRead::finish(int) (AioRequest.h:40)
| | | | ->96.68% (2,910,846,976B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->96.68% (2,910,846,976B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->96.68% (2,910,846,976B) 0x76924D3: finish_contexts(CephContext*, std::list<Context*, std::allocator<Context*> >&, int) (Context.h:98)
| | | | ->96.68% (2,910,846,976B) 0x768BC69: ObjectCacher::bh_read_finish(long, sobject_t, unsigned long, long, unsigned long, ceph::buffer::list&, int, bool) (ObjectCacher.cc:794)
| | | | ->96.68% (2,910,846,976B) 0x76956E5: ObjectCacher::C_ReadFinish::finish(int) (ObjectCacher.h:489)
| | | | ->96.68% (2,910,846,976B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->96.68% (2,910,846,976B) 0x76796F6: librbd::C_Request::finish(int) (LibrbdWriteback.cc:55)
| | | | ->96.68% (2,910,846,976B) 0x7676DC2: librbd::context_cb(void*, void*) (LibrbdWriteback.cc:35)
| | | | ->96.68% (2,910,846,976B) 0x7A51F96: librados::C_AioComplete::finish(int) (AioCompletionImpl.h:175)
| | | | ->96.68% (2,910,846,976B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->96.68% (2,910,846,976B) 0x7ABD616: Finisher::finisher_thread_entry() (Finisher.cc:56)
| | | | ->96.68% (2,910,846,976B) 0x674884F: start_thread (in /lib64/libpthread-2.12.so)
| | | | ->96.68% (2,910,846,976B) 0xB4CF90B: clone (in /lib64/libc-2.12.so)
| | | |
| | | ->00.00% (0B) in 1+ places, all below ms_print's threshold (01.00%)
| | |
| | ->00.28% (8,388,608B) in 1+ places, all below ms_print's threshold (01.00%)
| |
| ->00.00% (32,768B) in 1+ places, all below ms_print's threshold (01.00%)
|
->01.16% (34,898,660B) in 320 places, all below massif's threshold (01.00%)
--------------------------------------------------------------------------------
n time(i) total(B) useful-heap(B) extra-heap(B) stacks(B)
--------------------------------------------------------------------------------
28 163,634,151,031 4,009,584,152 4,005,594,100 3,990,052 0
99.90% (4,005,594,100B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc.
->97.70% (3,917,512,841B) 0x7C20D8D: ceph::buffer::create(unsigned int) (buffer.cc:196)
| ->97.70% (3,917,479,936B) 0x7C20E63: ceph::buffer::ptr::ptr(unsigned int) (buffer.cc:261)
| | ->97.49% (3,909,091,328B) 0x769612A: Striper::StripedReadResult::assemble_result(CephContext*, ceph::buffer::list&, bool) (Striper.cc:326)
| | | ->97.49% (3,909,091,328B) 0x7642DA4: librbd::AioCompletion::finalize(CephContext*, long) (AioCompletion.cc:41)
| | | ->97.49% (3,909,091,328B) 0x7643515: librbd::AioCompletion::complete_request(CephContext*, long) (AioCompletion.cc:72)
| | | | ->97.49% (3,909,091,328B) 0x7643C7F: librbd::C_AioRead::finish(int) (AioCompletion.cc:98)
| | | | ->97.49% (3,909,091,328B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->97.49% (3,909,091,328B) 0x7642C2F: librbd::C_CacheRead::finish(int) (AioRequest.h:40)
| | | | ->97.49% (3,909,091,328B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->97.49% (3,909,091,328B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->97.49% (3,909,091,328B) 0x76924D3: finish_contexts(CephContext*, std::list<Context*, std::allocator<Context*> >&, int) (Context.h:98)
| | | | ->97.49% (3,909,091,328B) 0x768BC69: ObjectCacher::bh_read_finish(long, sobject_t, unsigned long, long, unsigned long, ceph::buffer::list&, int, bool) (ObjectCacher.cc:794)
| | | | ->97.49% (3,909,091,328B) 0x76956E5: ObjectCacher::C_ReadFinish::finish(int) (ObjectCacher.h:489)
| | | | ->97.49% (3,909,091,328B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->97.49% (3,909,091,328B) 0x76796F6: librbd::C_Request::finish(int) (LibrbdWriteback.cc:55)
| | | | ->97.49% (3,909,091,328B) 0x7676DC2: librbd::context_cb(void*, void*) (LibrbdWriteback.cc:35)
| | | | ->97.49% (3,909,091,328B) 0x7A51F96: librados::C_AioComplete::finish(int) (AioCompletionImpl.h:175)
| | | | ->97.49% (3,909,091,328B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->97.49% (3,909,091,328B) 0x7ABD616: Finisher::finisher_thread_entry() (Finisher.cc:56)
| | | | ->97.49% (3,909,091,328B) 0x674884F: start_thread (in /lib64/libpthread-2.12.so)
| | | | ->97.49% (3,909,091,328B) 0xB4CF90B: clone (in /lib64/libc-2.12.so)
| | | |
| | | ->00.00% (0B) in 1+ places, all below ms_print's threshold (01.00%)
| | |
| | ->00.21% (8,388,608B) in 1+ places, all below ms_print's threshold (01.00%)
| |
| ->00.00% (32,905B) in 1+ places, all below ms_print's threshold (01.00%)
|
->00.87% (34,944,794B) in 1+ places, all below ms_print's threshold (01.00%)
--------------------------------------------------------------------------------
n time(i) total(B) useful-heap(B) extra-heap(B) stacks(B)
--------------------------------------------------------------------------------
29 167,549,711,252 4,773,349,288 4,768,990,014 4,359,274 0
99.91% (4,768,990,014B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc.
->98.06% (4,680,876,169B) 0x7C20D8D: ceph::buffer::create(unsigned int) (buffer.cc:196)
| ->98.06% (4,680,843,264B) 0x7C20E63: ceph::buffer::ptr::ptr(unsigned int) (buffer.cc:261)
| | ->97.89% (4,672,454,656B) 0x769612A: Striper::StripedReadResult::assemble_result(CephContext*, ceph::buffer::list&, bool) (Striper.cc:326)
| | | ->97.89% (4,672,454,656B) 0x7642DA4: librbd::AioCompletion::finalize(CephContext*, long) (AioCompletion.cc:41)
| | | ->97.89% (4,672,454,656B) 0x7643515: librbd::AioCompletion::complete_request(CephContext*, long) (AioCompletion.cc:72)
| | | | ->97.89% (4,672,454,656B) 0x7643C7F: librbd::C_AioRead::finish(int) (AioCompletion.cc:98)
| | | | ->97.89% (4,672,454,656B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->97.89% (4,672,454,656B) 0x7642C2F: librbd::C_CacheRead::finish(int) (AioRequest.h:40)
| | | | ->97.89% (4,672,454,656B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->97.89% (4,672,454,656B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->97.89% (4,672,454,656B) 0x76924D3: finish_contexts(CephContext*, std::list<Context*, std::allocator<Context*> >&, int) (Context.h:98)
| | | | ->97.89% (4,672,454,656B) 0x768BC69: ObjectCacher::bh_read_finish(long, sobject_t, unsigned long, long, unsigned long, ceph::buffer::list&, int, bool) (ObjectCacher.cc:794)
| | | | ->97.89% (4,672,454,656B) 0x76956E5: ObjectCacher::C_ReadFinish::finish(int) (ObjectCacher.h:489)
| | | | ->97.89% (4,672,454,656B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->97.89% (4,672,454,656B) 0x76796F6: librbd::C_Request::finish(int) (LibrbdWriteback.cc:55)
| | | | ->97.89% (4,672,454,656B) 0x7676DC2: librbd::context_cb(void*, void*) (LibrbdWriteback.cc:35)
| | | | ->97.89% (4,672,454,656B) 0x7A51F96: librados::C_AioComplete::finish(int) (AioCompletionImpl.h:175)
| | | | ->97.89% (4,672,454,656B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->97.89% (4,672,454,656B) 0x7ABD616: Finisher::finisher_thread_entry() (Finisher.cc:56)
| | | | ->97.89% (4,672,454,656B) 0x674884F: start_thread (in /lib64/libpthread-2.12.so)
| | | | ->97.89% (4,672,454,656B) 0xB4CF90B: clone (in /lib64/libc-2.12.so)
| | | |
| | | ->00.00% (0B) in 1+ places, all below ms_print's threshold (01.00%)
| | |
| | ->00.18% (8,388,608B) in 1+ places, all below ms_print's threshold (01.00%)
| |
| ->00.00% (32,905B) in 1+ places, all below ms_print's threshold (01.00%)
|
->00.73% (34,977,380B) in 1+ places, all below ms_print's threshold (01.00%)
--------------------------------------------------------------------------------
n time(i) total(B) useful-heap(B) extra-heap(B) stacks(B)
--------------------------------------------------------------------------------
30 172,273,415,923 5,663,020,216 5,658,226,689 4,793,527 0
99.92% (5,658,226,689B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc.
->98.36% (5,570,068,617B) 0x7C20D8D: ceph::buffer::create(unsigned int) (buffer.cc:196)
| ->98.36% (5,570,035,712B) 0x7C20E63: ceph::buffer::ptr::ptr(unsigned int) (buffer.cc:261)
| | ->98.36% (5,570,035,712B) 0x769612A: Striper::StripedReadResult::assemble_result(CephContext*, ceph::buffer::list&, bool) (Striper.cc:326)
| | | ->98.36% (5,570,035,712B) 0x7642DA4: librbd::AioCompletion::finalize(CephContext*, long) (AioCompletion.cc:41)
| | | ->96.58% (5,469,372,416B) 0x7643515: librbd::AioCompletion::complete_request(CephContext*, long) (AioCompletion.cc:72)
| | | | ->96.58% (5,469,372,416B) 0x7643C7F: librbd::C_AioRead::finish(int) (AioCompletion.cc:98)
| | | | ->96.58% (5,469,372,416B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->96.58% (5,469,372,416B) 0x7642C2F: librbd::C_CacheRead::finish(int) (AioRequest.h:40)
| | | | ->96.58% (5,469,372,416B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->96.58% (5,469,372,416B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->96.58% (5,469,372,416B) 0x76924D3: finish_contexts(CephContext*, std::list<Context*, std::allocator<Context*> >&, int) (Context.h:98)
| | | | ->96.58% (5,469,372,416B) 0x768BC69: ObjectCacher::bh_read_finish(long, sobject_t, unsigned long, long, unsigned long, ceph::buffer::list&, int, bool) (ObjectCacher.cc:794)
| | | | ->96.58% (5,469,372,416B) 0x76956E5: ObjectCacher::C_ReadFinish::finish(int) (ObjectCacher.h:489)
| | | | ->96.58% (5,469,372,416B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->96.58% (5,469,372,416B) 0x76796F6: librbd::C_Request::finish(int) (LibrbdWriteback.cc:55)
| | | | ->96.58% (5,469,372,416B) 0x7676DC2: librbd::context_cb(void*, void*) (LibrbdWriteback.cc:35)
| | | | ->96.58% (5,469,372,416B) 0x7A51F96: librados::C_AioComplete::finish(int) (AioCompletionImpl.h:175)
| | | | ->96.58% (5,469,372,416B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->96.58% (5,469,372,416B) 0x7ABD616: Finisher::finisher_thread_entry() (Finisher.cc:56)
| | | | ->96.58% (5,469,372,416B) 0x674884F: start_thread (in /lib64/libpthread-2.12.so)
| | | | ->96.58% (5,469,372,416B) 0xB4CF90B: clone (in /lib64/libc-2.12.so)
| | | |
| | | ->01.78% (100,663,296B) 0x7644418: librbd::AioCompletion::finish_adding_requests(CephContext*) (AioCompletion.cc:27)
| | | ->01.78% (100,663,296B) 0x766BBDE: librbd::aio_read(librbd::ImageCtx*, std::vector<std::pair<unsigned long, unsigned long>, std::allocator<std::pair<unsigned long, unsigned long> > > const&, char*, ceph::buffer::list*, librbd::AioCompletion*) (internal.cc:3102)
| | | ->01.78% (100,663,296B) 0x7645D54: librbd::AioRequest::read_from_parent(std::vector<std::pair<unsigned long, unsigned long>, std::allocator<std::pair<unsigned long, unsigned long> > >&) (AioRequest.cc:52)
| | | ->01.78% (100,663,296B) 0x76468E8: librbd::AbstractWrite::should_complete(int) (AioRequest.cc:187)
| | | ->01.78% (100,663,296B) 0x7655581: librbd::rados_req_cb(void*, void*) (AioRequest.h:37)
| | | ->01.78% (100,663,296B) 0x7A51F16: librados::C_AioSafe::finish(int) (AioCompletionImpl.h:194)
| | | ->01.78% (100,663,296B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | ->01.78% (100,663,296B) 0x7ABD616: Finisher::finisher_thread_entry() (Finisher.cc:56)
| | | ->01.78% (100,663,296B) 0x674884F: start_thread (in /lib64/libpthread-2.12.so)
| | | ->01.78% (100,663,296B) 0xB4CF90B: clone (in /lib64/libc-2.12.so)
| | |
| | ->00.00% (0B) in 1+ places, all below ms_print's threshold (01.00%)
| |
| ->00.00% (32,905B) in 1+ places, all below ms_print's threshold (01.00%)
|
->00.62% (35,021,607B) in 1+ places, all below ms_print's threshold (01.00%)
--------------------------------------------------------------------------------
n time(i) total(B) useful-heap(B) extra-heap(B) stacks(B)
--------------------------------------------------------------------------------
31 178,728,383,028 1,304,981,272 1,301,520,440 3,460,832 0
32 185,180,761,716 1,279,628,760 1,276,190,709 3,438,051 0
33 189,487,655,207 2,118,785,024 2,114,954,708 3,830,316 0
34 193,799,081,188 1,027,293,592 1,024,051,220 3,242,372 0
99.68% (1,024,051,220B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc.
->90.64% (931,176,585B) 0x7C20D8D: ceph::buffer::create(unsigned int) (buffer.cc:196)
| ->90.64% (931,135,488B) 0x7C20E63: ceph::buffer::ptr::ptr(unsigned int) (buffer.cc:261)
| | ->89.82% (922,746,880B) 0x769612A: Striper::StripedReadResult::assemble_result(CephContext*, ceph::buffer::list&, bool) (Striper.cc:326)
| | | ->89.82% (922,746,880B) 0x7642DA4: librbd::AioCompletion::finalize(CephContext*, long) (AioCompletion.cc:41)
| | | ->89.82% (922,746,880B) 0x7643515: librbd::AioCompletion::complete_request(CephContext*, long) (AioCompletion.cc:72)
| | | | ->89.82% (922,746,880B) 0x7643C7F: librbd::C_AioRead::finish(int) (AioCompletion.cc:98)
| | | | ->89.82% (922,746,880B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->89.82% (922,746,880B) 0x7642C2F: librbd::C_CacheRead::finish(int) (AioRequest.h:40)
| | | | ->89.82% (922,746,880B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->89.82% (922,746,880B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->89.82% (922,746,880B) 0x76924D3: finish_contexts(CephContext*, std::list<Context*, std::allocator<Context*> >&, int) (Context.h:98)
| | | | ->89.82% (922,746,880B) 0x768BC69: ObjectCacher::bh_read_finish(long, sobject_t, unsigned long, long, unsigned long, ceph::buffer::list&, int, bool) (ObjectCacher.cc:794)
| | | | ->89.82% (922,746,880B) 0x76956E5: ObjectCacher::C_ReadFinish::finish(int) (ObjectCacher.h:489)
| | | | ->89.82% (922,746,880B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->89.82% (922,746,880B) 0x76796F6: librbd::C_Request::finish(int) (LibrbdWriteback.cc:55)
| | | | ->89.82% (922,746,880B) 0x7676DC2: librbd::context_cb(void*, void*) (LibrbdWriteback.cc:35)
| | | | ->89.82% (922,746,880B) 0x7A51F96: librados::C_AioComplete::finish(int) (AioCompletionImpl.h:175)
| | | | ->89.82% (922,746,880B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->89.82% (922,746,880B) 0x7ABD616: Finisher::finisher_thread_entry() (Finisher.cc:56)
| | | | ->89.82% (922,746,880B) 0x674884F: start_thread (in /lib64/libpthread-2.12.so)
| | | | ->89.82% (922,746,880B) 0xB4CF90B: clone (in /lib64/libc-2.12.so)
| | | |
| | | ->00.00% (0B) in 1+ places, all below ms_print's threshold (01.00%)
| | |
| | ->00.82% (8,388,608B) in 1+ places, all below ms_print's threshold (01.00%)
| |
| ->00.00% (41,097B) in 1+ places, all below ms_print's threshold (01.00%)
|
->02.45% (25,157,632B) 0x7C207E8: ceph::buffer::create_page_aligned(unsigned int) (buffer.cc:142)
| ->02.45% (25,153,536B) 0x7BA4EAB: Pipe::read_message(Message**) (Pipe.cc:1664)
| | ->02.45% (25,153,536B) 0x7BB39CF: Pipe::reader() (Pipe.cc:1399)
| | ->02.45% (25,153,536B) 0x7BB6C0B: Pipe::Reader::entry() (Pipe.h:47)
| | ->02.45% (25,153,536B) 0x674884F: start_thread (in /lib64/libpthread-2.12.so)
| | ->02.45% (25,153,536B) 0xB4CF90B: clone (in /lib64/libc-2.12.so)
| |
| ->00.00% (4,096B) in 1+ places, all below ms_print's threshold (01.00%)
|
->00.84% (8,604,544B) in 1+ places, all below ms_print's threshold (01.00%)
--------------------------------------------------------------------------------
n time(i) total(B) useful-heap(B) extra-heap(B) stacks(B)
--------------------------------------------------------------------------------
35 198,095,524,372 852,683,432 849,759,039 2,924,393 0
36 204,585,988,496 344,586,528 342,397,365 2,189,163 0
37 211,038,029,316 581,705,384 576,360,039 5,345,345 0
38 215,340,257,800 1,420,830,280 1,415,093,946 5,736,334 0
99.60% (1,415,093,946B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc.
->93.29% (1,325,457,603B) 0x7C20D8D: ceph::buffer::create(unsigned int) (buffer.cc:196)
| ->93.28% (1,325,400,064B) 0x7C20E63: ceph::buffer::ptr::ptr(unsigned int) (buffer.cc:261)
| | ->92.69% (1,317,011,456B) 0x769612A: Striper::StripedReadResult::assemble_result(CephContext*, ceph::buffer::list&, bool) (Striper.cc:326)
| | | ->92.69% (1,317,011,456B) 0x7642DA4: librbd::AioCompletion::finalize(CephContext*, long) (AioCompletion.cc:41)
| | | ->92.69% (1,317,011,456B) 0x7643515: librbd::AioCompletion::complete_request(CephContext*, long) (AioCompletion.cc:72)
| | | | ->92.69% (1,317,011,456B) 0x7643C7F: librbd::C_AioRead::finish(int) (AioCompletion.cc:98)
| | | | ->92.69% (1,317,011,456B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->92.69% (1,317,011,456B) 0x7642C2F: librbd::C_CacheRead::finish(int) (AioRequest.h:40)
| | | | ->92.69% (1,317,011,456B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->92.69% (1,317,011,456B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->92.69% (1,317,011,456B) 0x76924D3: finish_contexts(CephContext*, std::list<Context*, std::allocator<Context*> >&, int) (Context.h:98)
| | | | ->92.69% (1,317,011,456B) 0x768BC69: ObjectCacher::bh_read_finish(long, sobject_t, unsigned long, long, unsigned long, ceph::buffer::list&, int, bool) (ObjectCacher.cc:794)
| | | | ->92.69% (1,317,011,456B) 0x76956E5: ObjectCacher::C_ReadFinish::finish(int) (ObjectCacher.h:489)
| | | | ->92.69% (1,317,011,456B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->92.69% (1,317,011,456B) 0x76796F6: librbd::C_Request::finish(int) (LibrbdWriteback.cc:55)
| | | | ->92.69% (1,317,011,456B) 0x7676DC2: librbd::context_cb(void*, void*) (LibrbdWriteback.cc:35)
| | | | ->92.69% (1,317,011,456B) 0x7A51F96: librados::C_AioComplete::finish(int) (AioCompletionImpl.h:175)
| | | | ->92.69% (1,317,011,456B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->92.69% (1,317,011,456B) 0x7ABD616: Finisher::finisher_thread_entry() (Finisher.cc:56)
| | | | ->92.69% (1,317,011,456B) 0x674884F: start_thread (in /lib64/libpthread-2.12.so)
| | | | ->92.69% (1,317,011,456B) 0xB4CF90B: clone (in /lib64/libc-2.12.so)
| | | |
| | | ->00.00% (0B) in 1+ places, all below ms_print's threshold (01.00%)
| | |
| | ->00.59% (8,388,608B) in 1+ places, all below ms_print's threshold (01.00%)
| |
| ->00.00% (57,539B) in 1+ places, all below ms_print's threshold (01.00%)
|
->02.36% (33,542,144B) 0x7C207E8: ceph::buffer::create_page_aligned(unsigned int) (buffer.cc:142)
| ->02.36% (33,542,144B) 0x7BA4EAB: Pipe::read_message(Message**) (Pipe.cc:1664)
| | ->02.36% (33,542,144B) 0x7BB39CF: Pipe::reader() (Pipe.cc:1399)
| | ->02.36% (33,542,144B) 0x7BB6C0B: Pipe::Reader::entry() (Pipe.h:47)
| | ->02.36% (33,542,144B) 0x674884F: start_thread (in /lib64/libpthread-2.12.so)
| | ->02.36% (33,542,144B) 0xB4CF90B: clone (in /lib64/libc-2.12.so)
| |
| ->00.00% (0B) in 1+ places, all below ms_print's threshold (01.00%)
|
->00.72% (10,190,866B) in 1+ places, all below ms_print's threshold (01.00%)
--------------------------------------------------------------------------------
n time(i) total(B) useful-heap(B) extra-heap(B) stacks(B)
--------------------------------------------------------------------------------
39 219,678,714,848 681,433,432 676,150,023 5,283,409 0
40 224,000,340,278 1,537,458,296 1,531,749,329 5,708,967 0
41 228,299,608,721 2,376,775,432 2,370,652,734 6,122,698 0
42 232,630,220,582 3,199,305,600 3,192,773,415 6,532,185 0
43 236,934,180,104 4,046,770,008 4,039,855,446 6,914,562 0
99.83% (4,039,855,446B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc.
->97.43% (3,942,695,186B) 0x7C20D8D: ceph::buffer::create(unsigned int) (buffer.cc:196)
| ->97.43% (3,942,645,760B) 0x7C20E63: ceph::buffer::ptr::ptr(unsigned int) (buffer.cc:261)
| | ->97.22% (3,934,257,152B) 0x769612A: Striper::StripedReadResult::assemble_result(CephContext*, ceph::buffer::list&, bool) (Striper.cc:326)
| | | ->97.22% (3,934,257,152B) 0x7642DA4: librbd::AioCompletion::finalize(CephContext*, long) (AioCompletion.cc:41)
| | | ->55.97% (2,264,924,160B) 0x7643515: librbd::AioCompletion::complete_request(CephContext*, long) (AioCompletion.cc:72)
| | | | ->55.97% (2,264,924,160B) 0x7643C7F: librbd::C_AioRead::finish(int) (AioCompletion.cc:98)
| | | | ->55.97% (2,264,924,160B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->55.97% (2,264,924,160B) 0x7642C2F: librbd::C_CacheRead::finish(int) (AioRequest.h:40)
| | | | ->55.97% (2,264,924,160B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->55.97% (2,264,924,160B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->55.97% (2,264,924,160B) 0x76924D3: finish_contexts(CephContext*, std::list<Context*, std::allocator<Context*> >&, int) (Context.h:98)
| | | | ->55.97% (2,264,924,160B) 0x768BC69: ObjectCacher::bh_read_finish(long, sobject_t, unsigned long, long, unsigned long, ceph::buffer::list&, int, bool) (ObjectCacher.cc:794)
| | | | ->55.97% (2,264,924,160B) 0x76956E5: ObjectCacher::C_ReadFinish::finish(int) (ObjectCacher.h:489)
| | | | ->55.97% (2,264,924,160B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->55.97% (2,264,924,160B) 0x76796F6: librbd::C_Request::finish(int) (LibrbdWriteback.cc:55)
| | | | ->55.97% (2,264,924,160B) 0x7676DC2: librbd::context_cb(void*, void*) (LibrbdWriteback.cc:35)
| | | | ->55.97% (2,264,924,160B) 0x7A51F96: librados::C_AioComplete::finish(int) (AioCompletionImpl.h:175)
| | | | ->55.97% (2,264,924,160B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->55.97% (2,264,924,160B) 0x7ABD616: Finisher::finisher_thread_entry() (Finisher.cc:56)
| | | | ->55.97% (2,264,924,160B) 0x674884F: start_thread (in /lib64/libpthread-2.12.so)
| | | | ->55.97% (2,264,924,160B) 0xB4CF90B: clone (in /lib64/libc-2.12.so)
| | | |
| | | ->41.25% (1,669,332,992B) 0x7644418: librbd::AioCompletion::finish_adding_requests(CephContext*) (AioCompletion.cc:27)
| | | ->41.25% (1,669,332,992B) 0x766BBDE: librbd::aio_read(librbd::ImageCtx*, std::vector<std::pair<unsigned long, unsigned long>, std::allocator<std::pair<unsigned long, unsigned long> > > const&, char*, ceph::buffer::list*, librbd::AioCompletion*) (internal.cc:3102)
| | | ->41.25% (1,669,332,992B) 0x7645D54: librbd::AioRequest::read_from_parent(std::vector<std::pair<unsigned long, unsigned long>, std::allocator<std::pair<unsigned long, unsigned long> > >&) (AioRequest.cc:52)
| | | ->41.25% (1,669,332,992B) 0x76468E8: librbd::AbstractWrite::should_complete(int) (AioRequest.cc:187)
| | | ->41.25% (1,669,332,992B) 0x7655581: librbd::rados_req_cb(void*, void*) (AioRequest.h:37)
| | | ->41.25% (1,669,332,992B) 0x7A51F16: librados::C_AioSafe::finish(int) (AioCompletionImpl.h:194)
| | | ->41.25% (1,669,332,992B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | ->41.25% (1,669,332,992B) 0x7ABD616: Finisher::finisher_thread_entry() (Finisher.cc:56)
| | | ->41.25% (1,669,332,992B) 0x674884F: start_thread (in /lib64/libpthread-2.12.so)
| | | ->41.25% (1,669,332,992B) 0xB4CF90B: clone (in /lib64/libc-2.12.so)
| | |
| | ->00.21% (8,388,608B) in 1+ places, all below ms_print's threshold (01.00%)
| |
| ->00.00% (49,426B) in 1+ places, all below ms_print's threshold (01.00%)
|
->01.04% (41,914,368B) 0x7C207E8: ceph::buffer::create_page_aligned(unsigned int) (buffer.cc:142)
| ->01.04% (41,906,176B) 0x7BA4EAB: Pipe::read_message(Message**) (Pipe.cc:1664)
| | ->01.04% (41,906,176B) 0x7BB39CF: Pipe::reader() (Pipe.cc:1399)
| | ->01.04% (41,906,176B) 0x7BB6C0B: Pipe::Reader::entry() (Pipe.h:47)
| | ->01.04% (41,906,176B) 0x674884F: start_thread (in /lib64/libpthread-2.12.so)
| | ->01.04% (41,906,176B) 0xB4CF90B: clone (in /lib64/libc-2.12.so)
| |
| ->00.00% (8,192B) in 1+ places, all below ms_print's threshold (01.00%)
|
->00.24% (9,576,511B) in 1+ places, all below ms_print's threshold (01.00%)
--------------------------------------------------------------------------------
n time(i) total(B) useful-heap(B) extra-heap(B) stacks(B)
--------------------------------------------------------------------------------
44 241,233,125,397 4,785,275,096 4,778,011,193 7,263,903 0
45 245,529,916,049 395,845,416 394,015,836 1,829,580 0
46 249,827,860,832 109,629,832 109,223,737 406,095 0
47 254,173,148,083 135,638,984 134,376,910 1,262,074 0
48 258,470,121,169 122,984,016 122,481,471 502,545 0
99.59% (122,481,471B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc.
->27.25% (33,517,568B) 0x7C207E8: ceph::buffer::create_page_aligned(unsigned int) (buffer.cc:142)
| ->27.25% (33,517,568B) 0x7BA4EAB: Pipe::read_message(Message**) (Pipe.cc:1664)
| | ->27.25% (33,517,568B) 0x7BB39CF: Pipe::reader() (Pipe.cc:1399)
| | ->27.25% (33,517,568B) 0x7BB6C0B: Pipe::Reader::entry() (Pipe.h:47)
| | ->27.25% (33,517,568B) 0x674884F: start_thread (in /lib64/libpthread-2.12.so)
| | ->27.25% (33,517,568B) 0xB4CF90B: clone (in /lib64/libc-2.12.so)
| |
| ->00.00% (0B) in 1+ places, all below ms_print's threshold (01.00%)
|
->20.49% (25,202,688B) 0x7C20D8D: ceph::buffer::create(unsigned int) (buffer.cc:196)
| ->20.46% (25,165,824B) 0x7C20E63: ceph::buffer::ptr::ptr(unsigned int) (buffer.cc:261)
| | ->13.64% (16,777,216B) 0x769612A: Striper::StripedReadResult::assemble_result(CephContext*, ceph::buffer::list&, bool) (Striper.cc:326)
| | | ->13.64% (16,777,216B) 0x7642DA4: librbd::AioCompletion::finalize(CephContext*, long) (AioCompletion.cc:41)
| | | ->13.64% (16,777,216B) 0x7643515: librbd::AioCompletion::complete_request(CephContext*, long) (AioCompletion.cc:72)
| | | | ->13.64% (16,777,216B) 0x7643C7F: librbd::C_AioRead::finish(int) (AioCompletion.cc:98)
| | | | ->13.64% (16,777,216B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->13.64% (16,777,216B) 0x7642C2F: librbd::C_CacheRead::finish(int) (AioRequest.h:40)
| | | | ->13.64% (16,777,216B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->13.64% (16,777,216B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->13.64% (16,777,216B) 0x76924D3: finish_contexts(CephContext*, std::list<Context*, std::allocator<Context*> >&, int) (Context.h:98)
| | | | ->13.64% (16,777,216B) 0x768BC69: ObjectCacher::bh_read_finish(long, sobject_t, unsigned long, long, unsigned long, ceph::buffer::list&, int, bool) (ObjectCacher.cc:794)
| | | | ->13.64% (16,777,216B) 0x76956E5: ObjectCacher::C_ReadFinish::finish(int) (ObjectCacher.h:489)
| | | | ->13.64% (16,777,216B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->13.64% (16,777,216B) 0x76796F6: librbd::C_Request::finish(int) (LibrbdWriteback.cc:55)
| | | | ->13.64% (16,777,216B) 0x7676DC2: librbd::context_cb(void*, void*) (LibrbdWriteback.cc:35)
| | | | ->13.64% (16,777,216B) 0x7A51F96: librados::C_AioComplete::finish(int) (AioCompletionImpl.h:175)
| | | | ->13.64% (16,777,216B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->13.64% (16,777,216B) 0x7ABD616: Finisher::finisher_thread_entry() (Finisher.cc:56)
| | | | ->13.64% (16,777,216B) 0x674884F: start_thread (in /lib64/libpthread-2.12.so)
| | | | ->13.64% (16,777,216B) 0xB4CF90B: clone (in /lib64/libc-2.12.so)
| | | |
| | | ->00.00% (0B) in 1+ places, all below ms_print's threshold (01.00%)
| | |
| | ->06.82% (8,388,608B) 0x768B832: ObjectCacher::bh_read_finish(long, sobject_t, unsigned long, long, unsigned long, ceph::buffer::list&, int, bool) (ObjectCacher.cc:642)
| | | ->06.82% (8,388,608B) 0x76956E5: ObjectCacher::C_ReadFinish::finish(int) (ObjectCacher.h:489)
| | | ->06.82% (8,388,608B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | ->06.82% (8,388,608B) 0x76796F6: librbd::C_Request::finish(int) (LibrbdWriteback.cc:55)
| | | ->06.82% (8,388,608B) 0x7676DC2: librbd::context_cb(void*, void*) (LibrbdWriteback.cc:35)
| | | ->06.82% (8,388,608B) 0x7A51F96: librados::C_AioComplete::finish(int) (AioCompletionImpl.h:175)
| | | ->06.82% (8,388,608B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | ->06.82% (8,388,608B) 0x7ABD616: Finisher::finisher_thread_entry() (Finisher.cc:56)
| | | ->06.82% (8,388,608B) 0x674884F: start_thread (in /lib64/libpthread-2.12.so)
| | | ->06.82% (8,388,608B) 0xB4CF90B: clone (in /lib64/libc-2.12.so)
| | |
| | ->00.00% (0B) in 1+ places, all below ms_print's threshold (01.00%)
| |
| ->00.03% (36,864B) in 1+ places, all below ms_print's threshold (01.00%)
|
->02.56% (3,145,728B) 0xAEF1282: _pixman_bits_image_init (in /usr/lib64/libpixman-1.so.0.26.2)
| ->02.56% (3,145,728B) 0xAEF135A: pixman_image_create_bits (in /usr/lib64/libpixman-1.so.0.26.2)
| ->02.56% (3,145,728B) 0x355947: vnc_dpy_switch (vnc.c:585)
| | ->02.56% (3,145,728B) 0x3368C0: dpy_gfx_replace_surface (console.c:1424)
| | | ->02.56% (3,145,728B) 0x38E461: vga_update_display (vga.c:1699)
| | | | ->02.56% (3,145,728B) 0x3521EC: vnc_refresh (vnc.c:2741)
| | | | ->02.56% (3,145,728B) 0x335310: gui_update (console.c:1436)
| | | | ->02.56% (3,145,728B) 0x3173E9: qemu_run_timers (qemu-timer.c:394)
| | | | ->02.56% (3,145,728B) 0x31743B: qemu_run_all_timers (qemu-timer.c:453)
| | | | ->02.56% (3,145,728B) 0x2DC28B: main_loop_wait (main-loop.c:471)
| | | | ->02.56% (3,145,728B) 0x35B235: main (vl.c:2090)
| | | |
| | | ->00.00% (0B) in 1+ places, all below ms_print's threshold (01.00%)
| | |
| | ->00.00% (0B) in 1+ places, all below ms_print's threshold (01.00%)
| |
| ->00.00% (0B) in 1+ places, all below ms_print's threshold (01.00%)
|
->02.48% (3,052,816B) 0x358F3B: malloc_and_trace (vl.c:2830)
| ->02.03% (2,493,990B) 0x52767D1: g_malloc (in /lib64/libglib-2.0.so.0.2200.5)
| | ->01.71% (2,097,152B) 0x1E8C5D: qemu_coroutine_new (coroutine-ucontext.c:144)
| | | ->01.71% (2,097,152B) 0x31273F: qemu_coroutine_create (qemu-coroutine.c:44)
| | | ->01.71% (2,097,152B) in 2 places, all below massif's threshold (01.00%)
| | |
| | ->00.32% (396,838B) in 1+ places, all below ms_print's threshold (01.00%)
| |
| ->00.45% (558,826B) in 1+ places, all below ms_print's threshold (01.00%)
|
->01.82% (2,232,245B) in 317 places, all below massif's threshold (01.00%)
--------------------------------------------------------------------------------
n time(i) total(B) useful-heap(B) extra-heap(B) stacks(B)
--------------------------------------------------------------------------------
49 262,812,624,408 159,369,600 158,925,790 443,810 0
50 266,749,467,327 118,370,688 118,081,530 289,158 0
51 270,689,632,545 125,542,616 125,193,698 348,918 0
52 274,609,859,845 95,485,640 95,049,449 Updated by Josh Durgin over 10 years ago
- Assignee set to Josh Durgin
Excellent report! The massif output is really useful. It shows that there are a large number of buffers getting backed up in the finish queue. I think this is an unintended side effect of moving the blocking in the cache to the completion side rather than the request scheduling side.
Can you try with rbd_cache_block_writes_upfront=true? This goes back to the old behavior where writes may block before they start, instead of blocking all completions at the end to control the amount of dirty data.
Actions
#3
Updated by Ivan Mironov over 10 years ago
- File massif.out.11923 massif.out.11923 added
- File plot.svg plot.svg added
With "rbd_cache_block_writes_upfront=1" it's harder to catch with massif, but I still see memory usage spikes using atop (see attached plot.svg).
I tried to increase number of massif snapshot and got this:
--------------------------------------------------------------------------------
Command: /usr/libexec/qemu-kvm -name storage-benchmark-vm-1 -M pc-i440fx-1.6 -enable-kvm -m 3072 -smp 2,sockets=2,cores=1,threads=1 -uuid ec7d60dc-423b-db56-1e83-9781200b13b4 -no-user-config -nodefaults -rtc base=utc -no-hpet -boot c -drive file=rbd:storage-benchmark-vms/vm-image-4:rbd_cache=1:rbd_cache_block_writes_upfront=1:auth_supported=none:mon_host=192.168.0.1\:6789;192.168.0.2\:6789;192.168.0.3\:6789,if=none,id=drive-ide0-0-0,format=raw,cache=writeback -device ide-drive,bus=ide.0,unit=0,drive=drive-ide0-0-0,id=ide0-0-0 -drive file=/oneclickse/test//tests/current.iso,if=none,media=cdrom,id=drive-ide0-1-0,readonly=on,format=raw,cache=none -device ide-drive,bus=ide.1,unit=0,drive=drive-ide0-1-0,id=ide0-1-0 -usb -vnc 0.0.0.0:51 -vga cirrus -device virtio-balloon-pci,id=balloon0,bus=pci.0,addr=0x3
Massif arguments: --alloc-fn=g_malloc --alloc-fn=g_malloc0 --detailed-freq=1 --max-snapshots=1000
ms_print arguments: massif.out.11923
--------------------------------------------------------------------------------
GB
3.756^ #
| #
| #
| @#
| @#
| @#
| @#
| @@#
| @@#
| @@#
| @@#
| @@@# @ @
| @@@# @ @
| @@@#@ @ @@@
| @ @@@#@@@ @@@@
| @ @@@@#@@@ @@@@
| @ @@@ @@@@#@@@ @ @@@@
| @ @ @@@ @@@@#@@@ @@ @@@@@
| @ @@ @@@@@@@@@@@@@#@@@ @@ @@@@@ @
| @@ @@ @ @ @@@ @@@@@@@@@@@@@#@@@@@@ @@@@@@@@@@
0 +----------------------------------------------------------------------->Gi
0 275.2
...
--------------------------------------------------------------------------------
n time(i) total(B) useful-heap(B) extra-heap(B) stacks(B)
--------------------------------------------------------------------------------
450 182,898,014,358 4,033,481,144 4,028,451,933 5,029,211 0
99.88% (4,028,451,933B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc.
->97.54% (3,934,273,715B) 0x7C20D8D: ceph::buffer::create(unsigned int) (buffer.cc:196)
| ->97.54% (3,934,257,152B) 0x7C20E63: ceph::buffer::ptr::ptr(unsigned int) (buffer.cc:261)
| | ->97.54% (3,934,257,152B) 0x769612A: Striper::StripedReadResult::assemble_result(CephContext*, ceph::buffer::list&, bool) (Striper.cc:326)
| | | ->97.54% (3,934,257,152B) 0x7642DA4: librbd::AioCompletion::finalize(CephContext*, long) (AioCompletion.cc:41)
| | | ->75.91% (3,061,841,920B) 0x7643515: librbd::AioCompletion::complete_request(CephContext*, long) (AioCompletion.cc:72)
| | | | ->75.91% (3,061,841,920B) 0x7643C7F: librbd::C_AioRead::finish(int) (AioCompletion.cc:98)
| | | | ->75.91% (3,061,841,920B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->75.91% (3,061,841,920B) 0x7642C2F: librbd::C_CacheRead::finish(int) (AioRequest.h:40)
| | | | ->75.91% (3,061,841,920B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->75.91% (3,061,841,920B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->75.91% (3,061,841,920B) 0x76924D3: finish_contexts(CephContext*, std::list<Context*, std::allocator<Context*> >&, int) (Context.h:98)
| | | | ->75.91% (3,061,841,920B) 0x768BC69: ObjectCacher::bh_read_finish(long, sobject_t, unsigned long, long, unsigned long, ceph::buffer::list&, int, bool) (ObjectCacher.cc:794)
| | | | ->75.91% (3,061,841,920B) 0x76956E5: ObjectCacher::C_ReadFinish::finish(int) (ObjectCacher.h:489)
| | | | ->75.91% (3,061,841,920B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->75.91% (3,061,841,920B) 0x76796F6: librbd::C_Request::finish(int) (LibrbdWriteback.cc:55)
| | | | ->75.91% (3,061,841,920B) 0x7676DC2: librbd::context_cb(void*, void*) (LibrbdWriteback.cc:35)
| | | | ->75.91% (3,061,841,920B) 0x7A51F96: librados::C_AioComplete::finish(int) (AioCompletionImpl.h:175)
| | | | ->75.91% (3,061,841,920B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->75.91% (3,061,841,920B) 0x7ABD616: Finisher::finisher_thread_entry() (Finisher.cc:56)
| | | | ->75.91% (3,061,841,920B) 0x674884F: start_thread (in /lib64/libpthread-2.12.so)
| | | | ->75.91% (3,061,841,920B) 0xB4CF90B: clone (in /lib64/libc-2.12.so)
| | | |
| | | ->21.63% (872,415,232B) 0x7644418: librbd::AioCompletion::finish_adding_requests(CephContext*) (AioCompletion.cc:27)
| | | ->21.63% (872,415,232B) 0x766BBDE: librbd::aio_read(librbd::ImageCtx*, std::vector<std::pair<unsigned long, unsigned long>, std::allocator<std::pair<unsigned long, unsigned long> > > const&, char*, ceph::buffer::list*, librbd::AioCompletion*) (internal.cc:3102)
| | | ->21.63% (872,415,232B) 0x7645D54: librbd::AioRequest::read_from_parent(std::vector<std::pair<unsigned long, unsigned long>, std::allocator<std::pair<unsigned long, unsigned long> > >&) (AioRequest.cc:52)
| | | ->21.63% (872,415,232B) 0x76468E8: librbd::AbstractWrite::should_complete(int) (AioRequest.cc:187)
| | | | ->21.63% (872,415,232B) 0x7655581: librbd::rados_req_cb(void*, void*) (AioRequest.h:37)
| | | | ->21.63% (872,415,232B) 0x7A51F16: librados::C_AioSafe::finish(int) (AioCompletionImpl.h:194)
| | | | ->21.63% (872,415,232B) 0x76447B8: Context::complete(int) (Context.h:42)
| | | | ->21.63% (872,415,232B) 0x7ABD616: Finisher::finisher_thread_entry() (Finisher.cc:56)
| | | | ->21.63% (872,415,232B) 0x674884F: start_thread (in /lib64/libpthread-2.12.so)
| | | | ->21.63% (872,415,232B) 0xB4CF90B: clone (in /lib64/libc-2.12.so)
| | | |
| | | ->00.00% (0B) in 1+ places, all below ms_print's threshold (01.00%)
| | |
| | ->00.00% (0B) in 1+ places, all below ms_print's threshold (01.00%)
| |
| ->00.00% (16,563B) in 1+ places, all below ms_print's threshold (01.00%)
|
->01.40% (56,291,328B) 0x7C207E8: ceph::buffer::create_page_aligned(unsigned int) (buffer.cc:142)
| ->01.40% (56,291,328B) in 2 places, all below massif's threshold (01.00%)
|
->00.26% (10,613,757B) in 1+ places, all below ms_print's threshold (01.00%)
...
Updated by Ian Colle about 10 years ago
- Subject changed from High memory consumption of qemu/librdb with enabled cache to High memory consumption of qemu/librbd with enabled cache
Updated by Sage Weil about 10 years ago
- Severity changed from 3 - minor to 2 - major
Updated by Mark Nelson almost 10 years ago
During RBD performance testing using the librbd fio engine, I appear to be able to reproduce something that looks quite a bit like this, especially during 4K sequential writes. RSS memory usage appears to grow at roughly 20MB/s for the fio process. Setting rbd_cache_block_writes_upfront=1 may slow the rate of increase but does not solve the problem. Currently with that set the fio process is using 6.5GB of RSS memory and still growing.
I'll try to run the fio process under massif and/or memcheck to see if I can reproduce.
Updated by Xavier Trilla over 9 years ago
We are experiencing the same issue, even if we are using quite different software versions.
We have our setup running the following versions:
Ubuntu 14.04
Ceph 0.80.5
QEMU / KVM 2.0.0
Actually it's an OpenStack IceHouse nova-compute node... We have been doing some tests with librbd cache and we have noticed exactly the same behavior explained in this issue. Actually simple things like just starting a Windows Server 2012 image over KVM/QEMU produces exactly the same situation.
So far we have seen the qemu process increase go from 2x to 4x times it's normal size when launching 2GB RAM instances, even if we configure a maximum size of 256MB in the librbd cache settings.
If you need any information please just let me know.
Thanks.
Updated by Sage Weil over 9 years ago
- Status changed from New to Pending Backport
Updated by Josh Durgin over 9 years ago
FTR the commits fixing this are commit:4fc9fffc494abedac0a9b1ce44706343f18466f1 and commit:cdb7675a21c9107e3596c90c2b1598def3c6899f
Updated by Sage Weil over 9 years ago
- Backport set to firefly
backported to firefly. josh, should we do dumpling too?
Updated by Sage Weil over 9 years ago
- Status changed from Pending Backport to Resolved
- Backport changed from firefly to firefly, dumpling
ok did dumpling too
Updated by Xavier Trilla over 9 years ago
Hi Sage,
Is this fix already released in FireFly 0.80.7 ? I've been checking the release notes of 80.6 and 80.7 and I cannot find any reference to this fix. Is it scheduled for the next release?
Thanks!
Actions