GNOME.org
 

[tracker/extractor-controller-thread: 6/7] tracker-extract: Cleaned up logging

commit dd83412689df363071e2ad6e1f06fca707bb9a9a
Author: Martyn Russell <martyn lanedo com>
Date:   Tue Apr 12 12:59:59 2011 +0100

    tracker-extract: Cleaned up logging
    
    Now all the thread tracing has to be turned on specifically with:
    
      -D THREAD_ENABLE_TRACE
    
    The MP3 extractor was also dumping all frame debugging, this has to be
    turned on with:
    
      -D FRAME_ENABLE_TRACE
    
    Some other sanity checking has been added to the logging so we know
    the max bytes from the config in the log.
    
    Things are more sane now with verbosity set to 2

 src/tracker-extract/tracker-controller.c  |   72 ++++++++++++++++++++++++-----
 src/tracker-extract/tracker-extract-mp3.c |    6 ++
 src/tracker-extract/tracker-extract.c     |   35 ++++++++++----
 src/tracker-extract/tracker-main.c        |   22 ++++++++-
 4 files changed, 111 insertions(+), 24 deletions(-)
---
diff --git a/src/tracker-extract/tracker-controller.c b/src/tracker-extract/tracker-controller.c
index 4aaaf9a..51cb6c8 100644
--- a/src/tracker-extract/tracker-controller.c
+++ b/src/tracker-extract/tracker-controller.c
@@ -29,6 +29,14 @@
 #include <libtracker-miner/tracker-miner.h>
 #include <gio/gio.h>
 
+#ifdef STAYALIVE_ENABLE_TRACE
+#warning Stayalive traces enabled
+#endif /* STAYALIVE_ENABLE_TRACE */
+
+#ifdef THREAD_ENABLE_TRACE
+#warning Controller thread traces enabled
+#endif /* THREAD_ENABLE_TRACE */
+
 typedef struct TrackerControllerPrivate TrackerControllerPrivate;
 typedef struct GetMetadataData GetMetadataData;
 
@@ -294,7 +302,11 @@ reset_shutdown_timeout_cb (gpointer user_data)
 {
 	TrackerControllerPrivate *priv;
 
-	g_message ("Extractor lifetime has expired");
+#ifdef STAYALIVE_ENABLE_TRACE
+	g_debug ("Stayalive --- time has expired");
+#endif /* STAYALIVE_ENABLE_TRACE */
+
+	g_message ("Shutting down due to no activity");
 
 	priv = TRACKER_CONTROLLER (user_data)->priv;
 	g_main_loop_quit (priv->main_loop);
@@ -314,7 +326,9 @@ reset_shutdown_timeout (TrackerController *controller)
 		return;
 	}
 
-	g_message ("(Re)setting shutdown timeout");
+#ifdef STAYALIVE_ENABLE_TRACE
+	g_debug ("Stayalive --- (Re)setting timeout");
+#endif /* STAYALIVE_ENABLE_TRACE */
 
 	if (priv->shutdown_source) {
 		g_source_destroy (priv->shutdown_source);
@@ -410,7 +424,12 @@ get_metadata_cb (GObject      *object,
 	} else {
 		GError *error = NULL;
 
-		g_message ("Controller thread (%p) got error back", g_thread_self ());
+
+#ifdef THREAD_ENABLE_TRACE
+		g_debug ("Thread:%p (Controller) --> Got error back",
+		         g_thread_self ());
+#endif /* THREAD_ENABLE_TRACE */
+
 		g_simple_async_result_propagate_error (G_SIMPLE_ASYNC_RESULT (res), &error);
 		tracker_dbus_request_end (data->request, error);
 		g_dbus_method_invocation_return_gerror (data->invocation, error);
@@ -462,7 +481,10 @@ get_metadata_fast_cb (GObject      *object,
 		GDataOutputStream *data_output_stream;
 		GError *error = NULL;
 
-		g_message ("Controller thread (%p) got metadata back", g_thread_self ());
+#ifdef THREAD_ENABLE_TRACE
+		g_debug ("Thread:%p (Controller) --> Got metadata back",
+		         g_thread_self ());
+#endif /* THREAD_ENABLE_TRACE */
 
 		unix_output_stream = g_unix_output_stream_new (data->fd, TRUE);
 		buffered_output_stream = g_buffered_output_stream_new_sized (unix_output_stream,
@@ -534,7 +556,11 @@ get_metadata_fast_cb (GObject      *object,
 	} else {
 		GError *error = NULL;
 
-		g_message ("Controller thread (%p) got error back", g_thread_self ());
+#ifdef THREAD_ENABLE_TRACE
+		g_debug ("Thread:%p (Controller) --> Got error back",
+		         g_thread_self ());
+#endif /* THREAD_ENABLE_TRACE */
+
 		g_simple_async_result_propagate_error (G_SIMPLE_ASYNC_RESULT (res), &error);
 		tracker_dbus_request_end (data->request, error);
 		g_dbus_method_invocation_return_gerror (data->invocation, error);
@@ -558,9 +584,6 @@ handle_method_call_get_metadata_fast (TrackerController	    *controller,
 	connection = g_dbus_method_invocation_get_connection (invocation);
 	method_message = g_dbus_method_invocation_get_message (invocation);
 
-	reset_shutdown_timeout (controller);
-	request = tracker_dbus_request_begin (NULL, "%s", __FUNCTION__);
-
 	if (g_dbus_connection_get_capabilities (connection) & G_DBUS_CAPABILITY_FLAGS_UNIX_FD_PASSING) {
 		TrackerControllerPrivate *priv;
 		GetMetadataData *data;
@@ -570,8 +593,17 @@ handle_method_call_get_metadata_fast (TrackerController	    *controller,
 		GError *error = NULL;
 
 		priv = controller->priv;
+
 		g_variant_get (parameters, "(&s&sh)", &uri, &mime, &index_fd);
 
+		request = tracker_dbus_request_begin (NULL,
+		                                      "%s (uri:'%s', mime:'%s', index_fd:%d)",
+		                                      __FUNCTION__,
+		                                      uri,
+		                                      mime,
+		                                      index_fd);
+		reset_shutdown_timeout (controller);
+
 		fd_list = g_dbus_message_get_unix_fd_list (method_message);
 
 		if ((fd = g_unix_fd_list_get (fd_list, index_fd, &error)) != -1) {
@@ -589,6 +621,10 @@ handle_method_call_get_metadata_fast (TrackerController	    *controller,
 			g_error_free (error);
 		}
 	} else {
+		request = tracker_dbus_request_begin (NULL,
+		                                      "%s (uri:'n/a', mime:'n/a', index_fd:unknown)",
+		                                      __FUNCTION__);
+		reset_shutdown_timeout (controller);
 		tracker_dbus_request_end (request, NULL);
 		g_dbus_method_invocation_return_dbus_error (invocation,
 		                                            TRACKER_EXTRACT_SERVICE ".GetMetadataFastError",
@@ -776,7 +812,10 @@ tracker_controller_thread_func (gpointer user_data)
 	TrackerControllerPrivate *priv;
 	GError *error = NULL;
 
-	g_message ("Controller thread '%p' created, dispatching...", g_thread_self ());
+#ifdef THREAD_ENABLE_TRACE
+	g_debug ("Thread:%p (Controller) --- Created, dispatching...",
+	         g_thread_self ());
+#endif /* THREAD_ENABLE_TRACE */
 
 	controller = user_data;
 	priv = controller->priv;
@@ -795,7 +834,10 @@ tracker_controller_thread_func (gpointer user_data)
 
 	g_main_loop_run (priv->main_loop);
 
-	g_message ("Shutting down...");
+#ifdef THREAD_ENABLE_TRACE
+	g_debug ("Thread:%p (Controller) --- Shutting down...",
+	         g_thread_self ());
+#endif /* THREAD_ENABLE_TRACE */
 
 	g_object_unref (controller);
 
@@ -820,7 +862,10 @@ tracker_controller_start (TrackerController  *controller,
 
 	priv = controller->priv;
 
-	g_message ("Waiting for controller thread to initialize...");
+#ifdef THREAD_ENABLE_TRACE
+	g_debug ("Thread:%p (Controller) --- Waiting for controller thread to initialize...",
+	         g_thread_self ());
+#endif /* THREAD_ENABLE_TRACE */
 
 	/* Wait for the controller thread to notify initialization */
 	g_mutex_lock (priv->initialization_mutex);
@@ -837,7 +882,10 @@ tracker_controller_start (TrackerController  *controller,
 		return FALSE;
 	}
 
-	g_message ("Controller thread initialized");
+#ifdef THREAD_ENABLE_TRACE
+	g_debug ("Thread:%p (Controller) --- Initialized",
+	         g_thread_self ());
+#endif /* THREAD_ENABLE_TRACE */
 
 	return TRUE;
 }
diff --git a/src/tracker-extract/tracker-extract-mp3.c b/src/tracker-extract/tracker-extract-mp3.c
index 51cf1e7..5968581 100644
--- a/src/tracker-extract/tracker-extract-mp3.c
+++ b/src/tracker-extract/tracker-extract-mp3.c
@@ -46,6 +46,10 @@
 
 #include "tracker-albumart.h"
 
+#ifdef FRAME_ENABLE_TRACE
+#warning Frame traces enabled
+#endif /* FRAME_ENABLE_TRACE */
+
 /* We mmap the beginning of the file and read separately the last 128
  * bytes for id3v1 tags. While these are probably cornercases the
  * rationale is that we don't want to fault a whole page for the last
@@ -1239,7 +1243,9 @@ get_id3v24_tags (id3v24frame           frame,
 			g_strstrip (word);
 		}
 
+#ifdef FRAME_ENABLE_TRACE
 		g_debug ("Frame is %d, word is %s", frame, word);
+#endif /* FRAME_ENABLE_TRACE */
 
 		switch (frame) {
 		case ID3V24_TALB:
diff --git a/src/tracker-extract/tracker-extract.c b/src/tracker-extract/tracker-extract.c
index 66aa320..ce99c6c 100644
--- a/src/tracker-extract/tracker-extract.c
+++ b/src/tracker-extract/tracker-extract.c
@@ -41,6 +41,10 @@
 #include "tracker-topanalyzer.h"
 #endif /* HAVE_STREAMANALYZER */
 
+#ifdef THREAD_ENABLE_TRACE
+#warning Main thread traces enabled
+#endif /* THREAD_ENABLE_TRACE */
+
 #define MAX_EXTRACT_TIME 10
 
 #define UNKNOWN_METHOD_MESSAGE "Method \"%s\" with signature \"%s\" on " \
@@ -414,7 +418,11 @@ get_metadata_cb (gpointer user_data)
 	TrackerExtractTask *task = user_data;
 	TrackerExtractInfo *info;
 
-	g_message ("Main thread (%p) got file to get metadata from: %s", g_thread_self (), task->file);
+#ifdef THREAD_ENABLE_TRACE
+	g_debug ("Thread:%p (Main) --> File:'%s' - Extracted",
+	         g_thread_self (),
+	         task->file);
+#endif /* THREAD_ENABLE_TRACE */
 
 	if (task->cancellable &&
 	    g_cancellable_is_cancelled (task->cancellable)) {
@@ -433,7 +441,8 @@ get_metadata_cb (gpointer user_data)
 	                       &info->preupdate,
 	                       &info->statements,
 	                       &info->where)) {
-		g_simple_async_result_set_op_res_gpointer ((GSimpleAsyncResult *) task->res, info,
+		g_simple_async_result_set_op_res_gpointer ((GSimpleAsyncResult *) task->res,
+		                                           info,
 		                                           (GDestroyNotify) tracker_extract_info_free);
 	} else {
 		g_simple_async_result_set_error ((GSimpleAsyncResult *) task->res,
@@ -465,11 +474,15 @@ tracker_extract_file (TrackerExtract      *extract,
 	g_return_if_fail (file != NULL);
 	g_return_if_fail (cb != NULL);
 
-	g_message ("Extract file on thread %p\n", g_thread_self ());
+#ifdef THREAD_ENABLE_TRACE
+	g_debug ("Thread:%p (Main) <-- File:'%s' - Extracting\n",
+	         g_thread_self (),
+	         file);
+#endif /* THREAD_ENABLE_TRACE */
+
 	res = g_simple_async_result_new (G_OBJECT (extract), cb, user_data, NULL);
 
-	task = extract_task_new (extract, file, mimetype, cancellable,
-	                         G_ASYNC_RESULT (res));
+	task = extract_task_new (extract, file, mimetype, cancellable, G_ASYNC_RESULT (res));
 	g_idle_add (get_metadata_cb, task);
 
 	/* task takes a ref */
@@ -490,8 +503,9 @@ tracker_extract_get_metadata_by_cmdline (TrackerExtract *object,
 
 	g_return_if_fail (uri != NULL);
 
-	if (get_file_metadata (object, uri, mime,
-			       &preupdate, &statements, &where)) {
+	g_message ("Extracting...");
+
+	if (get_file_metadata (object, uri, mime, &preupdate, &statements, &where)) {
 		const gchar *preupdate_str, *statements_str;
 
 		preupdate_str = statements_str = NULL;
@@ -504,11 +518,12 @@ tracker_extract_get_metadata_by_cmdline (TrackerExtract *object,
 			preupdate_str = tracker_sparql_builder_get_result (preupdate);
 		}
 
-		g_print ("Preupdate SPARQL:\n%s\n",
+		g_print ("SPARQL pre-update:\n%s\n",
 		         preupdate_str ? preupdate_str : "");
-		g_print ("Item SPARQL:\n%s\n",
+		g_print ("SPARQL item:\n%s\n",
 		         statements_str ? statements_str : "");
-		g_print ("Where clause: %s\n", where ? where : "");
+		g_print ("SPARQL where clause:\n%s\n",
+		         where ? where : "");
 
 		g_object_unref (statements);
 		g_object_unref (preupdate);
diff --git a/src/tracker-extract/tracker-main.c b/src/tracker-extract/tracker-main.c
index e0adfc0..b2e1b01 100644
--- a/src/tracker-extract/tracker-main.c
+++ b/src/tracker-extract/tracker-main.c
@@ -54,6 +54,10 @@
 #include "tracker-extract.h"
 #include "tracker-controller.h"
 
+#ifdef THREAD_ENABLE_TRACE
+#warning Main thread traces enabled
+#endif /* THREAD_ENABLE_TRACE */
+
 #define ABOUT	  \
 	"Tracker " PACKAGE_VERSION "\n"
 
@@ -234,13 +238,22 @@ log_handler (const gchar    *domain,
 	}
 }
 
+static void
+sanity_check_option_values (TrackerConfig *config)
+{
+	g_message ("General options:");
+	g_message ("  Verbosity  ............................  %d",
+	           tracker_config_get_verbosity (config));
+	g_message ("  Max bytes (per file)  .................  %d",
+	           tracker_config_get_max_bytes (config));
+}
+
 TrackerConfig *
 tracker_main_get_config (void)
 {
 	return config;
 }
 
-
 static int
 run_standalone (void)
 {
@@ -377,6 +390,8 @@ main (int argc, char *argv[])
 	g_print ("Starting log:\n  File:'%s'\n", log_filename);
 	g_free (log_filename);
 
+	sanity_check_option_values (config);
+
 	/* This makes sure we don't steal all the system's resources */
 	initialize_priority ();
 	tracker_memory_setrlimits ();
@@ -410,7 +425,10 @@ main (int argc, char *argv[])
 		return EXIT_FAILURE;
         }
 
-	g_message ("Main thread (%p) waiting for extract requests...", g_thread_self ());
+#ifdef THREAD_ENABLE_TRACE
+        g_debug ("Thread:%p (Main) --- Waiting for extract requests...",
+                 g_thread_self ());
+#endif /* THREAD_ENABLE_TRACE */
 
 	tracker_locale_init ();
 	tracker_albumart_init ();
[Date Prev][Date Next]   [Thread Prev][Thread Next]   [Thread Index] [Date Index] [Author Index]