Activity log for bug #1663186

Date Who What changed Old value New value Message
2017-02-09 09:51:24 Robert Whitton bug added bug
2017-02-09 09:51:24 Robert Whitton attachment added tmp.txt https://bugs.launchpad.net/bugs/1663186/+attachment/4815778/+files/tmp.txt
2017-02-09 10:20:46 Robert Whitton description Nemo version: nemo 2.2.4. Running under debian jessie release 8.7. Copying nearly a million (small) files from local disk to a USB2 attached hard disk (not a memory stick). A total copy of 8.7GiB, really not very large. The copy started quickly but become slower and slower. After nearly a day the rate of copying had dropped to a pathetic ~100KiB/s. "top" shows that one of the CPU cores is ~100% busy. I took a profile of nemo (using perf) and it shows: # To display the perf.data header info, please use --header/--header-only options. # # Samples: 12K of event 'cycles' # Event count (approx.): 11388387380 # # Overhead Command Shared Object Symbol # ........ ....... ............................. ................................................ # 98.76% pool libglib-2.0.so.0.4200.1 [.] g_list_last 0.07% nemo libglib-2.0.so.0.4200.1 [.] g_slice_alloc 0.07% nemo libc-2.19.so [.] _int_malloc 0.04% nemo libpango-1.0.so.0.3600.8 [.] pango_find_paragraph_boundary 0.03% nemo libglib-2.0.so.0.4200.1 [.] g_hash_table_lookup 0.03% nemo libgobject-2.0.so.0.4200.1 [.] g_type_value_table_peek 0.03% pool libc-2.19.so [.] malloc 0.03% nemo libglib-2.0.so.0.4200.1 [.] g_slice_free_chain_with_offset 0.03% gmain libc-2.19.so [.] _IO_no_init 0.02% pool libglib-2.0.so.0.4200.1 [.] g_slice_alloc 0.02% nemo [kernel.kallsyms] [k] msecs_to_jiffies 0.02% nemo libc-2.19.so [.] strlen 0.02% nemo libcairo.so.2.11400.0 [.] 0x00000000000461f3 0.02% nemo libdbus-1.so.3.8.14 [.] dbus_connection_get_dispatch_status 0.02% nemo libharfbuzz.so.0.935.0 [.] 0x00000000000189cd 0.02% nemo libpangocairo-1.0.so.0.3600.8 [.] 0x00000000000065c8 0.02% nemo libgobject-2.0.so.0.4200.1 [.] g_type_check_instance_is_a 0.02% nemo libgdk-3.so.0.1400.5 [.] 0x000000000005b2b2 0.02% nemo libc-2.19.so [.] malloc 0.02% nemo libglib-2.0.so.0.4200.1 [.] g_pointer_bit_lock 0.02% pool libglib-2.0.so.0.4200.1 [.] g_hash_table_lookup_extended < SNIPPED THE REMAINING INSIGNIFICANT ENTRIES, FILE ATTACHED FOR FULL OUTPUT > 98.76% of the time we are in g_list_last? That doesn't sound good. If I had to guess I would suggest the we have some computation here that's O(N^X) where X is > 0 and N is the number of files already copied. So it gets slower and slower as the copy progresses. Nemo version: nemo 2.2.4. Running under debian jessie release 8.7. Copying nearly a million (small) files from local disk to a USB2 attached hard disk (not a memory stick). A total copy of 8.7GiB, really not very large. The copy started quickly but become slower and slower. After nearly a day the rate of copying had dropped to a pathetic ~100KiB/s. "top" shows that one of the CPU cores is ~100% busy. I took a profile of nemo (using perf) and it shows: # To display the perf.data header info, please use --header/--header-only options. # # Samples: 12K of event 'cycles' # Event count (approx.): 11388387380 # # Overhead Command Shared Object Symbol # ........ ....... ............................. ................................................ #     98.76% pool libglib-2.0.so.0.4200.1 [.] g_list_last      0.07% nemo libglib-2.0.so.0.4200.1 [.] g_slice_alloc      0.07% nemo libc-2.19.so [.] _int_malloc      0.04% nemo libpango-1.0.so.0.3600.8 [.] pango_find_paragraph_boundary      0.03% nemo libglib-2.0.so.0.4200.1 [.] g_hash_table_lookup      0.03% nemo libgobject-2.0.so.0.4200.1 [.] g_type_value_table_peek      0.03% pool libc-2.19.so [.] malloc      0.03% nemo libglib-2.0.so.0.4200.1 [.] g_slice_free_chain_with_offset      0.03% gmain libc-2.19.so [.] _IO_no_init      0.02% pool libglib-2.0.so.0.4200.1 [.] g_slice_alloc      0.02% nemo [kernel.kallsyms] [k] msecs_to_jiffies      0.02% nemo libc-2.19.so [.] strlen      0.02% nemo libcairo.so.2.11400.0 [.] 0x00000000000461f3      0.02% nemo libdbus-1.so.3.8.14 [.] dbus_connection_get_dispatch_status      0.02% nemo libharfbuzz.so.0.935.0 [.] 0x00000000000189cd      0.02% nemo libpangocairo-1.0.so.0.3600.8 [.] 0x00000000000065c8      0.02% nemo libgobject-2.0.so.0.4200.1 [.] g_type_check_instance_is_a      0.02% nemo libgdk-3.so.0.1400.5 [.] 0x000000000005b2b2      0.02% nemo libc-2.19.so [.] malloc      0.02% nemo libglib-2.0.so.0.4200.1 [.] g_pointer_bit_lock      0.02% pool libglib-2.0.so.0.4200.1 [.] g_hash_table_lookup_extended < SNIPPED THE REMAINING INSIGNIFICANT ENTRIES, FILE ATTACHED FOR FULL OUTPUT > 98.76% of the time we are in g_list_last? That doesn't sound good. If I had to guess I would suggest the we have some computation here that's O(N^X) where X is > 0 and N is the number of files already copied. So it gets slower and slower as the copy progresses. Let's look at the implementation of libglib... The implementation of g_list_last is truly appalling as the list gets longer... { if (list) { while (list->next) list = list->next; } return list; } i.e. it appears to walk the list from the head until it encounters the last element. I'd strongly suggest that nemo avoids direct or indirect use of g_list_last since this is likely to offer very poor performance when the list becomes long.
2017-02-24 15:52:35 Robert Whitton linuxmint: status New Incomplete
2017-02-24 15:52:45 Robert Whitton linuxmint: status Incomplete New