2006-11-14 Federico Mena Quintero Provide logging information on the client side about calls into the VFS daemon. We'll use this to see what kind of delays people are getting with fat-locked, in-daemon methods like SMB. * libgnomevfs/gnome-vfs-daemon-method.c (get_incremented_serial): New utility function; returns a different serial number each time it is called. (log_operation_start): New function; logs the start of an operation. (log_operation_end): New function; logs the end of an operation. (do_open): Log OPEN. (do_create): Log CREATE. (do_close): Log CLOSE. (do_read): Log READ. (do_write): Log WRITE. (do_seek): Log SEEK. (do_tell): Log TELL. (do_truncate_handle): Log TRUNCATE_HANDLE. (do_open_directory): Log OPEN_DIRECTORY. (do_close_directory): Log CLOSE_DIRECTORY. (do_read_directory): Log READ_DIRECTORY. (do_get_file_info): Log GET_FILE_INFO. (do_get_file_info_from_handle): Log GET_FILE_INFO_FROM_HANDLE. (do_is_local): Log IS_LOCAL. (do_make_directory): Log MAKE_DIRECTORY. (do_remove_directory): Log REMOVE_DIRECTORY. (do_move): Log MOVE. (do_unlink): Log UNLINK. (do_check_same_fs): Log CHECK_SAME_FS. (do_set_file_info): Log SET_FILE_INFO. (do_truncate): Log TRUNCATE. (do_find_directory): Log FIND_DIRECTORY. (do_create_symbolic_link): Log CREATE_SYMBOLIC_LINK. --- gnome-vfs-no-debug-log/libgnomevfs/gnome-vfs-daemon-method.c 2005-04-13 14:58:54.000000000 -0500 +++ gnome-vfs-2.12.2/libgnomevfs/gnome-vfs-daemon-method.c 2006-11-14 15:19:24.000000000 -0600 @@ -33,6 +33,43 @@ typedef struct { int current_pos; } DaemonDirHandle; +static GStaticMutex operation_serial_mutex = G_STATIC_MUTEX_INIT; +static int operation_serial_number; + +static int +get_incremented_serial (void) +{ + int retval; + + g_static_mutex_lock (&operation_serial_mutex); + operation_serial_number++; + retval = operation_serial_number; + g_static_mutex_unlock (&operation_serial_mutex); + + return retval; +} + +static int +log_operation_start (const char *op_name, const char *uri_str) +{ + int serial; + + serial = get_incremented_serial (); + g_debug ("%s issued (%d)%s%s", + op_name, + serial, + uri_str ? ": " : "", + uri_str ? uri_str : ""); + + return serial; +} + +static void +log_operation_end (const char *op_name, int serial) +{ + g_debug ("%s replied (%d)", op_name, serial); +} + static void daemon_dir_handle_free (DaemonDirHandle *handle) { @@ -151,6 +188,7 @@ do_open (GnomeVFSMethod *method, GNOME_VFS_DaemonHandle handle; char *uri_str; GnomeVFSClientCall *client_call; + int serial; client = _gnome_vfs_get_client (); daemon = _gnome_vfs_client_get_async_daemon (client); @@ -165,6 +203,8 @@ do_open (GnomeVFSMethod *method, CORBA_exception_init (&ev); handle = CORBA_OBJECT_NIL; + + serial = log_operation_start ("OPEN", uri_str); res = GNOME_VFS_AsyncDaemon_Open (daemon, &handle, uri_str, @@ -172,6 +212,7 @@ do_open (GnomeVFSMethod *method, BONOBO_OBJREF (client_call), BONOBO_OBJREF (client), &ev); + log_operation_end ("OPEN", serial); if (handle != CORBA_OBJECT_NIL) { /* Don't allow reentrancy on handle method @@ -212,6 +253,7 @@ do_create (GnomeVFSMethod *method, GNOME_VFS_DaemonHandle handle; char *uri_str; GnomeVFSClientCall *client_call; + int serial; client = _gnome_vfs_get_client (); daemon = _gnome_vfs_client_get_async_daemon (client); @@ -226,6 +268,8 @@ do_create (GnomeVFSMethod *method, CORBA_exception_init (&ev); handle = CORBA_OBJECT_NIL; + + serial = log_operation_start ("CREATE", uri_str); res = GNOME_VFS_AsyncDaemon_Create (daemon, &handle, uri_str, @@ -235,6 +279,7 @@ do_create (GnomeVFSMethod *method, BONOBO_OBJREF (client_call), BONOBO_OBJREF (client), &ev); + log_operation_end ("CREATE", serial); if (handle != CORBA_OBJECT_NIL) { /* Don't allow reentrancy on handle method @@ -269,6 +314,7 @@ do_close (GnomeVFSMethod *method, CORBA_Environment ev; GnomeVFSClientCall *client_call; GnomeVFSClient *client; + int serial; g_return_val_if_fail (method_handle != NULL, GNOME_VFS_ERROR_INTERNAL); @@ -276,10 +322,13 @@ do_close (GnomeVFSMethod *method, client_call = _gnome_vfs_client_call_get (context); CORBA_exception_init (&ev); + + serial = log_operation_start ("CLOSE", NULL); res = GNOME_VFS_DaemonHandle_Close ((GNOME_VFS_DaemonHandle) method_handle, BONOBO_OBJREF (client_call), BONOBO_OBJREF (client), &ev); + log_operation_end ("CLOSE", serial); _gnome_vfs_client_call_finished (client_call, context); @@ -308,16 +357,20 @@ do_read (GnomeVFSMethod *method, GNOME_VFS_buffer *buf; GnomeVFSClientCall *client_call; GnomeVFSClient *client; + int serial; client = _gnome_vfs_get_client (); client_call = _gnome_vfs_client_call_get (context); CORBA_exception_init (&ev); + + serial = log_operation_start ("READ", NULL); res = GNOME_VFS_DaemonHandle_Read ((GNOME_VFS_DaemonHandle) method_handle, &buf, num_bytes, BONOBO_OBJREF (client_call), BONOBO_OBJREF (client), &ev); + log_operation_end ("READ", serial); _gnome_vfs_client_call_finished (client_call, context); @@ -352,6 +405,7 @@ do_write (GnomeVFSMethod *method, GnomeVFSClientCall *client_call; GnomeVFSClient *client; GNOME_VFS_FileSize bytes_written_return; + int serial; g_return_val_if_fail (method_handle != NULL, GNOME_VFS_ERROR_INTERNAL); @@ -362,12 +416,14 @@ do_write (GnomeVFSMethod *method, buf._maximum = buf._length = num_bytes; buf._buffer = (unsigned char *)buffer; buf._release = 0; - + + serial = log_operation_start ("WRITE", NULL); res = GNOME_VFS_DaemonHandle_Write ((GNOME_VFS_DaemonHandle) method_handle, &buf, &bytes_written_return, BONOBO_OBJREF (client_call), BONOBO_OBJREF (client), &ev); + log_operation_end ("WRITE", serial); _gnome_vfs_client_call_finished (client_call, context); @@ -392,17 +448,20 @@ do_seek (GnomeVFSMethod *method, CORBA_Environment ev; GnomeVFSClientCall *client_call; GnomeVFSClient *client; + int serial; g_return_val_if_fail (method_handle != NULL, GNOME_VFS_ERROR_INTERNAL); client = _gnome_vfs_get_client (); client_call = _gnome_vfs_client_call_get (context); - + + serial = log_operation_start ("SEEK", NULL); res = GNOME_VFS_DaemonHandle_Seek ((GNOME_VFS_DaemonHandle) method_handle, whence, offset, BONOBO_OBJREF (client_call), BONOBO_OBJREF (client), &ev); + log_operation_end ("SEEK", serial); _gnome_vfs_client_call_finished (client_call, context); @@ -424,17 +483,21 @@ do_tell (GnomeVFSMethod *method, GnomeVFSClientCall *client_call; GnomeVFSClient *client; GNOME_VFS_FileOffset offset; + int serial; g_return_val_if_fail (method_handle != NULL, GNOME_VFS_ERROR_INTERNAL); client = _gnome_vfs_get_client (); client_call = _gnome_vfs_client_call_get (NULL); - + + serial = log_operation_start ("TELL", NULL); res = GNOME_VFS_DaemonHandle_Tell ((GNOME_VFS_DaemonHandle) method_handle, &offset, BONOBO_OBJREF (client_call), BONOBO_OBJREF (client), &ev); + log_operation_end ("TELL", serial); + *offset_return = (GnomeVFSFileOffset) offset; _gnome_vfs_client_call_finished (client_call, NULL); @@ -457,17 +520,20 @@ do_truncate_handle (GnomeVFSMethod *meth CORBA_Environment ev; GnomeVFSClientCall *client_call; GnomeVFSClient *client; + int serial; g_return_val_if_fail (method_handle != NULL, GNOME_VFS_ERROR_INTERNAL); client = _gnome_vfs_get_client (); client_call = _gnome_vfs_client_call_get (context); - + + serial = log_operation_start ("TRUNCATE_HANDLE", NULL); res = GNOME_VFS_DaemonHandle_Truncate ((GNOME_VFS_DaemonHandle) method_handle, where, BONOBO_OBJREF (client_call), BONOBO_OBJREF (client), &ev); + log_operation_end ("TRUNCATE_HANDLE", serial); _gnome_vfs_client_call_finished (client_call, context); @@ -494,6 +560,7 @@ do_open_directory (GnomeVFSMethod *metho char *uri_str; GnomeVFSClientCall *client_call; DaemonDirHandle *dir_handle; + int serial; client = _gnome_vfs_get_client (); daemon = _gnome_vfs_client_get_async_daemon (client); @@ -508,6 +575,8 @@ do_open_directory (GnomeVFSMethod *metho CORBA_exception_init (&ev); handle = CORBA_OBJECT_NIL; + + serial = log_operation_start ("OPEN_DIRECTORY", uri_str); res = GNOME_VFS_AsyncDaemon_OpenDirectory (daemon, &handle, uri_str, @@ -515,6 +584,7 @@ do_open_directory (GnomeVFSMethod *metho BONOBO_OBJREF (client_call), BONOBO_OBJREF (client), &ev); + log_operation_end ("OPEN_DIRECTORY", serial); if (handle != CORBA_OBJECT_NIL) { /* Don't allow reentrancy on handle method @@ -554,6 +624,7 @@ do_close_directory (GnomeVFSMethod *meth GnomeVFSClientCall *client_call; GnomeVFSClient *client; DaemonDirHandle *dir_handle; + int serial; g_return_val_if_fail (method_handle != NULL, GNOME_VFS_ERROR_INTERNAL); @@ -563,10 +634,13 @@ do_close_directory (GnomeVFSMethod *meth client_call = _gnome_vfs_client_call_get (context); CORBA_exception_init (&ev); + + serial = log_operation_start ("CLOSE_DIRECTORY", NULL); res = GNOME_VFS_DaemonDirHandle_Close (dir_handle->corba_handle, BONOBO_OBJREF (client_call), BONOBO_OBJREF (client), &ev); + log_operation_end ("CLOSE_DIRECTORY", serial); _gnome_vfs_client_call_finished (client_call, context); @@ -595,6 +669,7 @@ do_read_directory (GnomeVFSMethod *metho GNOME_VFS_FileInfoList *list; DaemonDirHandle *dir_handle; GNOME_VFS_FileInfo *corba_info; + int serial; g_return_val_if_fail (method_handle != NULL, GNOME_VFS_ERROR_INTERNAL); @@ -605,11 +680,14 @@ do_read_directory (GnomeVFSMethod *metho client_call = _gnome_vfs_client_call_get (context); CORBA_exception_init (&ev); + + serial = log_operation_start ("READ_DIRECTORY", NULL); res = GNOME_VFS_DaemonDirHandle_Read (dir_handle->corba_handle, &list, BONOBO_OBJREF (client_call), BONOBO_OBJREF (client), &ev); + log_operation_end ("READ_DIRECTORY", serial); _gnome_vfs_client_call_finished (client_call, context); @@ -658,6 +736,7 @@ do_get_file_info (GnomeVFSMethod *method char *uri_str; GnomeVFSClientCall *client_call; GNOME_VFS_FileInfo *corba_info; + int serial; client = _gnome_vfs_get_client (); daemon = _gnome_vfs_client_get_async_daemon (client); @@ -672,6 +751,8 @@ do_get_file_info (GnomeVFSMethod *method CORBA_exception_init (&ev); handle = CORBA_OBJECT_NIL; + + serial = log_operation_start ("GET_FILE_INFO", uri_str); res = GNOME_VFS_AsyncDaemon_GetFileInfo (daemon, uri_str, &corba_info, @@ -679,6 +760,7 @@ do_get_file_info (GnomeVFSMethod *method BONOBO_OBJREF (client_call), BONOBO_OBJREF (client), &ev); + log_operation_end ("GET_FILE_INFO", serial); _gnome_vfs_client_call_finished (client_call, context); g_free (uri_str); @@ -712,18 +794,22 @@ do_get_file_info_from_handle (GnomeVFSMe GNOME_VFS_DaemonHandle handle; GnomeVFSClientCall *client_call; GNOME_VFS_FileInfo *corba_info; + int serial; client = _gnome_vfs_get_client (); client_call = _gnome_vfs_client_call_get (context); CORBA_exception_init (&ev); handle = CORBA_OBJECT_NIL; + + serial = log_operation_start ("GET_FILE_INFO_FROM_HANDLE", NULL); res = GNOME_VFS_DaemonHandle_GetFileInfo ((GNOME_VFS_DaemonHandle) method_handle, &corba_info, options, BONOBO_OBJREF (client_call), BONOBO_OBJREF (client), &ev); + log_operation_end ("GET_FILE_INFO_FROM_HANDLE", serial); _gnome_vfs_client_call_finished (client_call, context); @@ -751,6 +837,7 @@ do_is_local (GnomeVFSMethod *method, CORBA_Environment ev; char *uri_str; GnomeVFSClientCall *client_call; + int serial; client = _gnome_vfs_get_client (); daemon = _gnome_vfs_client_get_async_daemon (client); @@ -764,11 +851,14 @@ do_is_local (GnomeVFSMethod *method, client_call = _gnome_vfs_client_call_get (NULL); CORBA_exception_init (&ev); + + serial = log_operation_start ("IS_LOCAL", uri_str); res = GNOME_VFS_AsyncDaemon_IsLocal (daemon, uri_str, BONOBO_OBJREF (client_call), BONOBO_OBJREF (client), &ev); + log_operation_end ("IS_LOCAL", serial); _gnome_vfs_client_call_finished (client_call, NULL); @@ -798,6 +888,7 @@ do_make_directory (GnomeVFSMethod *metho GNOME_VFS_DaemonHandle handle; char *uri_str; GnomeVFSClientCall *client_call; + int serial; client = _gnome_vfs_get_client (); daemon = _gnome_vfs_client_get_async_daemon (client); @@ -812,12 +903,15 @@ do_make_directory (GnomeVFSMethod *metho CORBA_exception_init (&ev); handle = CORBA_OBJECT_NIL; + + serial = log_operation_start ("MAKE_DIRECTORY", uri_str); res = GNOME_VFS_AsyncDaemon_MakeDirectory (daemon, uri_str, perm, BONOBO_OBJREF (client_call), BONOBO_OBJREF (client), &ev); + log_operation_end ("MAKE_DIRECTORY", serial); _gnome_vfs_client_call_finished (client_call, context); g_free (uri_str); @@ -844,6 +938,7 @@ do_remove_directory (GnomeVFSMethod *met GNOME_VFS_DaemonHandle handle; char *uri_str; GnomeVFSClientCall *client_call; + int serial; client = _gnome_vfs_get_client (); daemon = _gnome_vfs_client_get_async_daemon (client); @@ -858,11 +953,14 @@ do_remove_directory (GnomeVFSMethod *met CORBA_exception_init (&ev); handle = CORBA_OBJECT_NIL; + + serial = log_operation_start ("REMOVE_DIRECTORY", uri_str); res = GNOME_VFS_AsyncDaemon_RemoveDirectory (daemon, uri_str, BONOBO_OBJREF (client_call), BONOBO_OBJREF (client), &ev); + log_operation_end ("REMOVE_DIRECTORY", serial); _gnome_vfs_client_call_finished (client_call, context); g_free (uri_str); @@ -892,6 +990,8 @@ do_move (GnomeVFSMethod *method, char *old_uri_str; char *new_uri_str; GnomeVFSClientCall *client_call; + int serial; + char *fake_uri_str; client = _gnome_vfs_get_client (); daemon = _gnome_vfs_client_get_async_daemon (client); @@ -907,6 +1007,10 @@ do_move (GnomeVFSMethod *method, CORBA_exception_init (&ev); handle = CORBA_OBJECT_NIL; + + fake_uri_str = g_strconcat (old_uri_str, " -> ", new_uri_str, NULL); + serial = log_operation_start ("MOVE", fake_uri_str); + g_free (fake_uri_str); res = GNOME_VFS_AsyncDaemon_Move (daemon, old_uri_str, new_uri_str, @@ -914,6 +1018,7 @@ do_move (GnomeVFSMethod *method, BONOBO_OBJREF (client_call), BONOBO_OBJREF (client), &ev); + log_operation_end ("MOVE", serial); _gnome_vfs_client_call_finished (client_call, context); g_free (old_uri_str); @@ -941,6 +1046,7 @@ do_unlink (GnomeVFSMethod *method, GNOME_VFS_DaemonHandle handle; char *uri_str; GnomeVFSClientCall *client_call; + int serial; client = _gnome_vfs_get_client (); daemon = _gnome_vfs_client_get_async_daemon (client); @@ -955,11 +1061,14 @@ do_unlink (GnomeVFSMethod *method, CORBA_exception_init (&ev); handle = CORBA_OBJECT_NIL; + + serial = log_operation_start ("UNLINK", uri_str); res = GNOME_VFS_AsyncDaemon_Unlink (daemon, uri_str, BONOBO_OBJREF (client_call), BONOBO_OBJREF (client), &ev); + log_operation_end ("UNLINK", serial); _gnome_vfs_client_call_finished (client_call, context); g_free (uri_str); @@ -990,6 +1099,8 @@ do_check_same_fs (GnomeVFSMethod *method char *target_uri_str; GnomeVFSClientCall *client_call; CORBA_boolean same_fs; + int serial; + char *fake_uri_str; client = _gnome_vfs_get_client (); daemon = _gnome_vfs_client_get_async_daemon (client); @@ -1005,6 +1116,10 @@ do_check_same_fs (GnomeVFSMethod *method CORBA_exception_init (&ev); handle = CORBA_OBJECT_NIL; + + fake_uri_str = g_strconcat (source_uri_str, ", ", target_uri_str, NULL); + serial = log_operation_start ("CHECK_SAME_FS", fake_uri_str); + g_free (fake_uri_str); res = GNOME_VFS_AsyncDaemon_CheckSameFS (daemon, source_uri_str, target_uri_str, @@ -1012,6 +1127,8 @@ do_check_same_fs (GnomeVFSMethod *method BONOBO_OBJREF (client_call), BONOBO_OBJREF (client), &ev); + log_operation_end ("CHECK_SAME_FS", serial); + *same_fs_return = same_fs; _gnome_vfs_client_call_finished (client_call, context); @@ -1043,6 +1160,7 @@ do_set_file_info (GnomeVFSMethod *method char *uri_str; GnomeVFSClientCall *client_call; GNOME_VFS_FileInfo *corba_info; + int serial; client = _gnome_vfs_get_client (); daemon = _gnome_vfs_client_get_async_daemon (client); @@ -1060,6 +1178,8 @@ do_set_file_info (GnomeVFSMethod *method CORBA_exception_init (&ev); handle = CORBA_OBJECT_NIL; + + serial = log_operation_start ("SET_FILE_INFO", uri_str); res = GNOME_VFS_AsyncDaemon_SetFileInfo (daemon, uri_str, corba_info, @@ -1067,6 +1187,7 @@ do_set_file_info (GnomeVFSMethod *method BONOBO_OBJREF (client_call), BONOBO_OBJREF (client), &ev); + log_operation_end ("SET_FILE_INFO", serial); _gnome_vfs_client_call_finished (client_call, context); g_free (uri_str); @@ -1090,6 +1211,7 @@ do_truncate (GnomeVFSMethod *method, GNOME_VFS_DaemonHandle handle; char *uri_str; GnomeVFSClientCall *client_call; + int serial; client = _gnome_vfs_get_client (); daemon = _gnome_vfs_client_get_async_daemon (client); @@ -1104,12 +1226,15 @@ do_truncate (GnomeVFSMethod *method, CORBA_exception_init (&ev); handle = CORBA_OBJECT_NIL; + + serial = log_operation_start ("TRUNCATE", uri_str); res = GNOME_VFS_AsyncDaemon_Truncate (daemon, uri_str, where, BONOBO_OBJREF (client_call), BONOBO_OBJREF (client), &ev); + log_operation_end ("TRUNCATE", serial); _gnome_vfs_client_call_finished (client_call, context); g_free (uri_str); @@ -1142,6 +1267,7 @@ do_find_directory (GnomeVFSMethod *metho char *near_uri_str; char *result_uri_str; GnomeVFSClientCall *client_call; + int serial; client = _gnome_vfs_get_client (); daemon = _gnome_vfs_client_get_async_daemon (client); @@ -1156,6 +1282,8 @@ do_find_directory (GnomeVFSMethod *metho CORBA_exception_init (&ev); handle = CORBA_OBJECT_NIL; + + serial = log_operation_start ("FIND_DIRECTORY", near_uri_str); res = GNOME_VFS_AsyncDaemon_FindDirectory (daemon, near_uri_str, kind, @@ -1166,6 +1294,7 @@ do_find_directory (GnomeVFSMethod *metho BONOBO_OBJREF (client_call), BONOBO_OBJREF (client), &ev); + log_operation_end ("FIND_DIRECTORY", serial); _gnome_vfs_client_call_finished (client_call, context); g_free (near_uri_str); @@ -1199,6 +1328,8 @@ do_create_symbolic_link (GnomeVFSMethod GNOME_VFS_DaemonHandle handle; char *uri_str; GnomeVFSClientCall *client_call; + int serial; + char *fake_uri_str; client = _gnome_vfs_get_client (); daemon = _gnome_vfs_client_get_async_daemon (client); @@ -1213,12 +1344,17 @@ do_create_symbolic_link (GnomeVFSMethod CORBA_exception_init (&ev); handle = CORBA_OBJECT_NIL; + + fake_uri_str = g_strconcat (uri_str, ", ", target_reference, NULL); + serial = log_operation_start ("CREATE_SYMBOLIC_LINK", fake_uri_str); + g_free (fake_uri_str); res = GNOME_VFS_AsyncDaemon_CreateSymbolicLink (daemon, uri_str, target_reference, BONOBO_OBJREF (client_call), BONOBO_OBJREF (client), &ev); + log_operation_end ("CREATE_SYMBOLIC_LINK", serial); _gnome_vfs_client_call_finished (client_call, context); g_free (uri_str);