Commit dd834126 authored by Martyn Russell's avatar Martyn Russell

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
parent 8093b8b0
...@@ -29,6 +29,14 @@ ...@@ -29,6 +29,14 @@
#include <libtracker-miner/tracker-miner.h> #include <libtracker-miner/tracker-miner.h>
#include <gio/gio.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 TrackerControllerPrivate TrackerControllerPrivate;
typedef struct GetMetadataData GetMetadataData; typedef struct GetMetadataData GetMetadataData;
...@@ -294,7 +302,11 @@ reset_shutdown_timeout_cb (gpointer user_data) ...@@ -294,7 +302,11 @@ reset_shutdown_timeout_cb (gpointer user_data)
{ {
TrackerControllerPrivate *priv; 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; priv = TRACKER_CONTROLLER (user_data)->priv;
g_main_loop_quit (priv->main_loop); g_main_loop_quit (priv->main_loop);
...@@ -314,7 +326,9 @@ reset_shutdown_timeout (TrackerController *controller) ...@@ -314,7 +326,9 @@ reset_shutdown_timeout (TrackerController *controller)
return; 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) { if (priv->shutdown_source) {
g_source_destroy (priv->shutdown_source); g_source_destroy (priv->shutdown_source);
...@@ -410,7 +424,12 @@ get_metadata_cb (GObject *object, ...@@ -410,7 +424,12 @@ get_metadata_cb (GObject *object,
} else { } else {
GError *error = NULL; 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); g_simple_async_result_propagate_error (G_SIMPLE_ASYNC_RESULT (res), &error);
tracker_dbus_request_end (data->request, error); tracker_dbus_request_end (data->request, error);
g_dbus_method_invocation_return_gerror (data->invocation, error); g_dbus_method_invocation_return_gerror (data->invocation, error);
...@@ -462,7 +481,10 @@ get_metadata_fast_cb (GObject *object, ...@@ -462,7 +481,10 @@ get_metadata_fast_cb (GObject *object,
GDataOutputStream *data_output_stream; GDataOutputStream *data_output_stream;
GError *error = NULL; 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); unix_output_stream = g_unix_output_stream_new (data->fd, TRUE);
buffered_output_stream = g_buffered_output_stream_new_sized (unix_output_stream, buffered_output_stream = g_buffered_output_stream_new_sized (unix_output_stream,
...@@ -534,7 +556,11 @@ get_metadata_fast_cb (GObject *object, ...@@ -534,7 +556,11 @@ get_metadata_fast_cb (GObject *object,
} else { } else {
GError *error = NULL; 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); g_simple_async_result_propagate_error (G_SIMPLE_ASYNC_RESULT (res), &error);
tracker_dbus_request_end (data->request, error); tracker_dbus_request_end (data->request, error);
g_dbus_method_invocation_return_gerror (data->invocation, error); g_dbus_method_invocation_return_gerror (data->invocation, error);
...@@ -558,9 +584,6 @@ handle_method_call_get_metadata_fast (TrackerController *controller, ...@@ -558,9 +584,6 @@ handle_method_call_get_metadata_fast (TrackerController *controller,
connection = g_dbus_method_invocation_get_connection (invocation); connection = g_dbus_method_invocation_get_connection (invocation);
method_message = g_dbus_method_invocation_get_message (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) { if (g_dbus_connection_get_capabilities (connection) & G_DBUS_CAPABILITY_FLAGS_UNIX_FD_PASSING) {
TrackerControllerPrivate *priv; TrackerControllerPrivate *priv;
GetMetadataData *data; GetMetadataData *data;
...@@ -570,8 +593,17 @@ handle_method_call_get_metadata_fast (TrackerController *controller, ...@@ -570,8 +593,17 @@ handle_method_call_get_metadata_fast (TrackerController *controller,
GError *error = NULL; GError *error = NULL;
priv = controller->priv; priv = controller->priv;
g_variant_get (parameters, "(&s&sh)", &uri, &mime, &index_fd); 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); fd_list = g_dbus_message_get_unix_fd_list (method_message);
if ((fd = g_unix_fd_list_get (fd_list, index_fd, &error)) != -1) { 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, ...@@ -589,6 +621,10 @@ handle_method_call_get_metadata_fast (TrackerController *controller,
g_error_free (error); g_error_free (error);
} }
} else { } 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); tracker_dbus_request_end (request, NULL);
g_dbus_method_invocation_return_dbus_error (invocation, g_dbus_method_invocation_return_dbus_error (invocation,
TRACKER_EXTRACT_SERVICE ".GetMetadataFastError", TRACKER_EXTRACT_SERVICE ".GetMetadataFastError",
...@@ -776,7 +812,10 @@ tracker_controller_thread_func (gpointer user_data) ...@@ -776,7 +812,10 @@ tracker_controller_thread_func (gpointer user_data)
TrackerControllerPrivate *priv; TrackerControllerPrivate *priv;
GError *error = NULL; 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; controller = user_data;
priv = controller->priv; priv = controller->priv;
...@@ -795,7 +834,10 @@ tracker_controller_thread_func (gpointer user_data) ...@@ -795,7 +834,10 @@ tracker_controller_thread_func (gpointer user_data)
g_main_loop_run (priv->main_loop); 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); g_object_unref (controller);
...@@ -820,7 +862,10 @@ tracker_controller_start (TrackerController *controller, ...@@ -820,7 +862,10 @@ tracker_controller_start (TrackerController *controller,
priv = controller->priv; 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 */ /* Wait for the controller thread to notify initialization */
g_mutex_lock (priv->initialization_mutex); g_mutex_lock (priv->initialization_mutex);
...@@ -837,7 +882,10 @@ tracker_controller_start (TrackerController *controller, ...@@ -837,7 +882,10 @@ tracker_controller_start (TrackerController *controller,
return FALSE; 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; return TRUE;
} }
...@@ -46,6 +46,10 @@ ...@@ -46,6 +46,10 @@
#include "tracker-albumart.h" #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 /* We mmap the beginning of the file and read separately the last 128
* bytes for id3v1 tags. While these are probably cornercases the * 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 * rationale is that we don't want to fault a whole page for the last
...@@ -1239,7 +1243,9 @@ get_id3v24_tags (id3v24frame frame, ...@@ -1239,7 +1243,9 @@ get_id3v24_tags (id3v24frame frame,
g_strstrip (word); g_strstrip (word);
} }
#ifdef FRAME_ENABLE_TRACE
g_debug ("Frame is %d, word is %s", frame, word); g_debug ("Frame is %d, word is %s", frame, word);
#endif /* FRAME_ENABLE_TRACE */
switch (frame) { switch (frame) {
case ID3V24_TALB: case ID3V24_TALB:
......
...@@ -41,6 +41,10 @@ ...@@ -41,6 +41,10 @@
#include "tracker-topanalyzer.h" #include "tracker-topanalyzer.h"
#endif /* HAVE_STREAMANALYZER */ #endif /* HAVE_STREAMANALYZER */
#ifdef THREAD_ENABLE_TRACE
#warning Main thread traces enabled
#endif /* THREAD_ENABLE_TRACE */
#define MAX_EXTRACT_TIME 10 #define MAX_EXTRACT_TIME 10
#define UNKNOWN_METHOD_MESSAGE "Method \"%s\" with signature \"%s\" on " \ #define UNKNOWN_METHOD_MESSAGE "Method \"%s\" with signature \"%s\" on " \
...@@ -414,7 +418,11 @@ get_metadata_cb (gpointer user_data) ...@@ -414,7 +418,11 @@ get_metadata_cb (gpointer user_data)
TrackerExtractTask *task = user_data; TrackerExtractTask *task = user_data;
TrackerExtractInfo *info; 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 && if (task->cancellable &&
g_cancellable_is_cancelled (task->cancellable)) { g_cancellable_is_cancelled (task->cancellable)) {
...@@ -433,7 +441,8 @@ get_metadata_cb (gpointer user_data) ...@@ -433,7 +441,8 @@ get_metadata_cb (gpointer user_data)
&info->preupdate, &info->preupdate,
&info->statements, &info->statements,
&info->where)) { &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); (GDestroyNotify) tracker_extract_info_free);
} else { } else {
g_simple_async_result_set_error ((GSimpleAsyncResult *) task->res, g_simple_async_result_set_error ((GSimpleAsyncResult *) task->res,
...@@ -465,11 +474,15 @@ tracker_extract_file (TrackerExtract *extract, ...@@ -465,11 +474,15 @@ tracker_extract_file (TrackerExtract *extract,
g_return_if_fail (file != NULL); g_return_if_fail (file != NULL);
g_return_if_fail (cb != 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); res = g_simple_async_result_new (G_OBJECT (extract), cb, user_data, NULL);
task = extract_task_new (extract, file, mimetype, cancellable, task = extract_task_new (extract, file, mimetype, cancellable, G_ASYNC_RESULT (res));
G_ASYNC_RESULT (res));
g_idle_add (get_metadata_cb, task); g_idle_add (get_metadata_cb, task);
/* task takes a ref */ /* task takes a ref */
...@@ -490,8 +503,9 @@ tracker_extract_get_metadata_by_cmdline (TrackerExtract *object, ...@@ -490,8 +503,9 @@ tracker_extract_get_metadata_by_cmdline (TrackerExtract *object,
g_return_if_fail (uri != NULL); g_return_if_fail (uri != NULL);
if (get_file_metadata (object, uri, mime, g_message ("Extracting...");
&preupdate, &statements, &where)) {
if (get_file_metadata (object, uri, mime, &preupdate, &statements, &where)) {
const gchar *preupdate_str, *statements_str; const gchar *preupdate_str, *statements_str;
preupdate_str = statements_str = NULL; preupdate_str = statements_str = NULL;
...@@ -504,11 +518,12 @@ tracker_extract_get_metadata_by_cmdline (TrackerExtract *object, ...@@ -504,11 +518,12 @@ tracker_extract_get_metadata_by_cmdline (TrackerExtract *object,
preupdate_str = tracker_sparql_builder_get_result (preupdate); 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 : ""); preupdate_str ? preupdate_str : "");
g_print ("Item SPARQL:\n%s\n", g_print ("SPARQL item:\n%s\n",
statements_str ? statements_str : ""); 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 (statements);
g_object_unref (preupdate); g_object_unref (preupdate);
......
...@@ -54,6 +54,10 @@ ...@@ -54,6 +54,10 @@
#include "tracker-extract.h" #include "tracker-extract.h"
#include "tracker-controller.h" #include "tracker-controller.h"
#ifdef THREAD_ENABLE_TRACE
#warning Main thread traces enabled
#endif /* THREAD_ENABLE_TRACE */
#define ABOUT \ #define ABOUT \
"Tracker " PACKAGE_VERSION "\n" "Tracker " PACKAGE_VERSION "\n"
...@@ -234,13 +238,22 @@ log_handler (const gchar *domain, ...@@ -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 * TrackerConfig *
tracker_main_get_config (void) tracker_main_get_config (void)
{ {
return config; return config;
} }
static int static int
run_standalone (void) run_standalone (void)
{ {
...@@ -377,6 +390,8 @@ main (int argc, char *argv[]) ...@@ -377,6 +390,8 @@ main (int argc, char *argv[])
g_print ("Starting log:\n File:'%s'\n", log_filename); g_print ("Starting log:\n File:'%s'\n", log_filename);
g_free (log_filename); g_free (log_filename);
sanity_check_option_values (config);
/* This makes sure we don't steal all the system's resources */ /* This makes sure we don't steal all the system's resources */
initialize_priority (); initialize_priority ();
tracker_memory_setrlimits (); tracker_memory_setrlimits ();
...@@ -410,7 +425,10 @@ main (int argc, char *argv[]) ...@@ -410,7 +425,10 @@ main (int argc, char *argv[])
return EXIT_FAILURE; 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_locale_init ();
tracker_albumart_init (); tracker_albumart_init ();
......
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment