After an evaluation, GNOME has moved from Bugzilla to GitLab. Learn more about GitLab.
No new issues can be reported in GNOME Bugzilla anymore.
To report an issue in a GNOME project, go to GNOME GitLab.
Do not go to GNOME Gitlab for: Bluefish, Doxygen, GnuCash, GStreamer, java-gnome, LDTP, NetworkManager, Tomboy.
Bug 320282 - Nautilus profiling with sysprof
Nautilus profiling with sysprof
Status: RESOLVED FIXED
Product: nautilus
Classification: Core
Component: general
0.x.x [obsolete]
Other Linux
: Normal enhancement
: ---
Assigned To: Nautilus Maintainers
Nautilus Maintainers
Depends on:
Blocks:
 
 
Reported: 2005-10-31 01:27 UTC by Emmanuele Bassi (:ebassi)
Modified: 2007-04-12 21:49 UTC
See Also:
GNOME target: ---
GNOME version: ---


Attachments
First profile run (71.73 KB, application/x-bzip)
2005-10-31 01:31 UTC, Emmanuele Bassi (:ebassi)
  Details
Second profile run (351.22 KB, application/x-bzip)
2005-10-31 01:32 UTC, Emmanuele Bassi (:ebassi)
  Details
Updated open/close profiling info from CVS HEAD (357.20 KB, application/x-bzip)
2006-02-08 23:53 UTC, Luis Menina
  Details
reduce number of is_needy() calls (9.14 KB, patch)
2006-02-23 22:53 UTC, Aivars Kalvans
none Details | Review
reduce number of is_needy() calls (10.03 KB, patch)
2006-02-28 08:12 UTC, Aivars Kalvans
none Details | Review

Description Emmanuele Bassi (:ebassi) 2005-10-31 01:27:46 UTC
Two profile runs done with Sysprof, by Luis Menina (who rocks).

The first is a profile of nautilus opening ten folders with one thousand,
non-empty, files each.

The second is a profile of nautilus opening and closing ten times the same
directory, with five thousands non-empty files.
Comment 1 Emmanuele Bassi (:ebassi) 2005-10-31 01:31:14 UTC
Created attachment 54108 [details]
First profile run

open, ten directories, 1000 files each
Comment 2 Emmanuele Bassi (:ebassi) 2005-10-31 01:32:04 UTC
Created attachment 54109 [details]
Second profile run

open/close, single folder, 5000 files, for ten times
Comment 3 Luis Menina 2006-02-08 23:45:33 UTC
Here is the test case:
======================
<testcase>
mkdir test-folder
cd test-folder
for n in $(seq 5000); do echo "This is file number $n" > file-$n; done
# start sysprof
for n in $(seq 10); do nautilus .; done
# stop sysprof
</testcase>

Just close the folder each time needed.
Comment 4 Luis Menina 2006-02-08 23:53:10 UTC
Created attachment 58967 [details]
Updated open/close profiling info from CVS HEAD

open/close, single folder, 5000 files, ten times
While in the first test from 2005 the g_utf8_to_utf16 function seemed a big overused (from what I understand, meaning its really unsure, i'm no optimization guru :-) ), this time, you may just give some attention to the "is_needy" function. It's called many times in many places, and seems to take some good amount time.

If some optimization guru (Federico ? Mathias ?) could confirm this, just to make sure it's a good starting point ;-) ?
Comment 5 Aivars Kalvans 2006-02-23 22:53:54 UTC
Created attachment 60027 [details] [review]
reduce number of is_needy() calls

Correct me if I'm wrong:

is_needy() checks if there is some job to be done for file. There are 3 groups of is_needy() calls: for high priority, for low priority and for extension queues.

nautilus_directory_add_file_to_work_queue() calls is_needy() with all possible arguments and if something is found, file is added to high priority queue.  

For each file in high priority queue all is_needy() with arguments for high priority queue are called. If anything is found, high priority jobs are started (xxxx_start()), but each calls it's own is_needy() again. If nothing is found, file is moved to next queue (low priority or extension queue), but before it is_needy() with arguments for low priority queue are called.

In the same way file is processed in low priority queue and extension queue.

So, is_needy() is called way too much for each file. I removed all calls except those in xxxx_start(). For the testcase with 5000 files number of is_needy() calls dropped from 105569 to 56216.
Comment 6 Alexander Larsson 2006-02-27 16:26:08 UTC
I don't think this patch is 100% correct. For instance, take this part:
@@ -3196,45 +3199,45 @@ start_or_stop_io (NautilusDirectory *dir
 	while (!nautilus_file_queue_is_empty (directory->details->high_priority_queue)) {
 		file = nautilus_file_queue_head (directory->details->high_priority_queue);
 
-		if (file_needs_high_priority_work_done (directory, file)) {
-			/* Start getting attributes if possible */
-			file_info_start (directory, file);
-			link_info_start (directory, file);
+		/* Start getting attributes if possible */
+		file_info_start (directory, file, &needy);
+		link_info_start (directory, file, &needy);
+
+		if (needy) {
 			return;
-		} else {
-			move_file_to_low_priority_queue (directory, file);
 		}
+
+		move_file_to_low_priority_queue (directory, file);
 	}

If we're already loading the file info for this file (directory->details->get_info_in_progress != NULL), then needy isn't correctly set, which means we move this file into the next queue. 

Also, whats up with the profile? I see sysprof reporting 0.01% "Self" in the list on the left, but 19.28% in the list on the right.

Anyway, I don't think we want to change this core code this late in the cycle. This has to wait until 2.16.

Comment 7 Aivars Kalvans 2006-02-28 08:12:27 UTC
Created attachment 60291 [details] [review]
reduce number of is_needy() calls

Fixed patch according to comment#6

nautilus-open-close-20060209.xml looks ok on my box: 19.28/20.71 both in list on the right and on the left (functions). List on the left (callers) should sum up to  19.28/20.71.
Comment 8 Aivars Kalvans 2006-03-29 09:25:04 UTC
So, 2.14 is released. Does anybody have time to review this patch?
Comment 9 Paolo Borelli 2006-06-04 16:03:56 UTC
can you send the patch to nautilus-list? nautilus developer tend to miss patches in bugzilla due to the high bugzilla traffic, so they prefer that patches are also sent to the mailing list.
Comment 10 Luis Menina 2007-03-26 11:25:45 UTC
What's the progress on this ? Has the patch been applied ? There's still people complaining about this, especially with 5400 RPM hard disks...
Comment 11 Paolo Borelli 2007-03-26 13:37:58 UTC
Luis: nautilus patches are reviewed only if sent to the mailing list. Yiu can send a mail with a pointer to this patch
Comment 12 Luis Menina 2007-03-28 00:07:03 UTC
I can't reproduce the testcase on my GNOME 2.18 jhbuild system:
Does anyone know how to launch the session bus so that nautilus is happy ? BTW, the application should complain if it can't find the session bus, not crash as it did.

Here's the output:
==================
[liberforce@donald test-folder]$ LC_ALL=C nautilus .
process 5384: D-Bus library appears to be incorrectly set up; failed to read machine uuid: Failed to open "/opt/gnome2/var/lib/dbus/machine-id": No such file or directory
See the manual page for dbus-uuidgen to correct this issue.
  D-Bus not built with -rdynamic so unable to print a backtrace
Variable "format" is not available.
Variable "address" is not available.
Variable "var_args" is not available.
Variable "var_args" is not available.
Backtrace limit of 200 exceeded
Backtrace limit of 200 exceeded
Backtrace limit of 200 exceeded

And here's the backtrace:
==========================
Distribution: Mandriva Linux release 2007.0 (Official) for i586
Gnome Release: 2.18.0 2007-03-18 (JHBuild)
BugBuddy Version: 2.18.0

System: Linux 2.6.17-11mdv #1 SMP Tue Feb 13 11:59:10 MST 2007 i686
X Vendor: The X.Org Foundation
X Vendor Release: 70101000
Selinux: No
Accessibility: Disabled
GTK+ Theme: Clearlooks
Icon Theme: gnome

Memory status: size: 20660224 vsize: 20660224 resident: 6840320 share: 5775360 rss: 6840320 rss_rlim: 4294967295
CPU usage: start_time: 1175040316 rtime: 6 utime: 6 stime: 0 cutime:0 cstime: 0 timeout: 0 it_real_value: 0 frequency: 100

Backtrace was generated from '/opt/gnome2/bin/nautilus'

Using host libthread_db library "/lib/i686/libthread_db.so.1".
`shared object read from target memory' has disappeared; keeping its symbols.
[Thread debugging using libthread_db enabled]
[New Thread -1227069760 (LWP 5409)]
0xbfffe410 in __kernel_vsyscall ()
  • #0 __kernel_vsyscall
  • #1 __waitpid_nocancel
    from /lib/i686/libpthread.so.0
  • #2 libgnomeui_segv_handle
    at gnome-ui-init.c line 865
  • #3 <signal handler called>
  • #4 __kernel_vsyscall
  • #5 raise
    from /lib/i686/libc.so.6
  • #6 abort
    from /lib/i686/libc.so.6
  • #7 _dbus_abort
    at dbus-sysdeps.c line 84
  • #8 _dbus_warn_check_failed
    at dbus-internals.c line 283
  • #9 _dbus_get_local_machine_uuid_encoded
    at dbus-internals.c line 728
  • #10 _dbus_get_autolaunch_address
    at dbus-sysdeps-unix.c line 2387
  • #11 _dbus_transport_open_autolaunch
    at dbus-transport.c line 259
  • #12 _dbus_transport_open
    at dbus-transport.c line 357
  • #13 _dbus_connection_open_internal
    at dbus-connection.c line 1665
  • #14 internal_bus_get
    at dbus-bus.c line 430
  • #15 _gnome_vfs_get_main_dbus_connection
    at gnome-vfs-dbus-utils.c line 151
  • #16 gnome_vfs_volume_monitor_client_init
    at gnome-vfs-volume-monitor-client.c line 374
  • #17 IA__g_type_create_instance
    at gtype.c line 1569
  • #18 g_object_constructor
    at gobject.c line 1041
  • #19 IA__g_object_newv
    at gobject.c line 937
  • #20 IA__g_object_new_valist
    at gobject.c line 981
  • #21 IA__g_object_new
    at gobject.c line 795
  • #22 _gnome_vfs_get_volume_monitor_internal
    at gnome-vfs-volume-monitor.c line 446
  • #23 gnome_vfs_get_volume_monitor
    at gnome-vfs-volume-monitor.c line 475
  • #24 nautilus_application_instance_init
    at nautilus-application.c line 184
  • #25 IA__g_type_create_instance
    at gtype.c line 1569
  • #26 g_object_constructor
    at gobject.c line 1041
  • #27 bonobo_object_constructor
    at bonobo-object.c line 818
  • #28 IA__g_object_newv
    at gobject.c line 937
  • #29 IA__g_object_new_valist
    at gobject.c line 981
  • #30 IA__g_object_new
    at gobject.c line 795
  • #31 nautilus_application_new
    at nautilus-application.c line 213
  • #32 main
    at nautilus-main.c line 532

Thread 1 (Thread -1227069760 (LWP 5409)):
#-1 0xbfffe410 in __kernel_vsyscall ()
No symbol table info available.
Comment 13 Luis Menina 2007-04-06 22:55:47 UTC
Sent a mail to the mailing list, still no replay...
http://mail.gnome.org/archives/nautilus-list/2007-March/msg00096.html
Comment 14 Alexander Larsson 2007-04-12 14:25:59 UTC
I commited a slightly changed patch.
Comment 15 Luis Menina 2007-04-12 21:49:59 UTC
Thanks a lot Alexander :-)