From f9ba9234a414782f8bb41c1286eefce6173c22b1 Mon Sep 17 00:00:00 2001 From: Sam Thursfield Date: Sun, 22 Sep 2019 19:16:08 +0200 Subject: Reduce the amount of log messages with TRACKER_VERBOSITY=1 I want to enable TRACKER_VERBOSITY=1 in CI, so that we have more detailed logs with tests fail in CI. However, there are quite a lot of unnecessary and repeated messages from libtracker-data at this level. Example before: (tracker-store:22279): Tracker-INFO: 19:09:04.552: Setting database locations (tracker-store:22279): Tracker-INFO: 19:09:04.552: Checking database directories exist (tracker-store:22279): Tracker-INFO: 19:09:04.552: Checking whether database files exist (tracker-store:22279): Tracker-INFO: 19:09:04.552: Could not find database file:'/tmp/tracker-test-kbgjyxpt/cache/tracker/meta.db', reindex will be forced (tracker-store:22279): Tracker-INFO: 19:09:04.552: Cleaning up database files for reindex (tracker-store:22279): Tracker-INFO: 19:09:04.552: Removing all database/storage files (tracker-store:22279): Tracker-INFO: 19:09:04.552: Removing database:'/tmp/tracker-test-kbgjyxpt/cache/tracker/meta.db' (tracker-store:22279): Tracker-INFO: 19:09:04.552: Creating database files, this may take a few moments... (tracker-store:22279): Tracker-INFO: 19:09:04.552: Opened sqlite3 database:'/tmp/tracker-test-kbgjyxpt/cache/tracker/meta.db' (tracker-store:22279): Tracker-INFO: 19:09:04.553: Setting page size to 8192 (tracker-store:22279): Tracker-INFO: 19:09:04.553: Setting cache size to 250 (tracker-store:22279): Tracker-INFO: 19:09:04.553: Closed sqlite3 database:'/tmp/tracker-test-kbgjyxpt/cache/tracker/meta.db' (tracker-store:22279): Tracker-INFO: 19:09:04.553: Opened sqlite3 database:'/tmp/tracker-test-kbgjyxpt/cache/tracker/meta.db' (tracker-store:22279): Tracker-INFO: 19:09:04.554: Setting page size to 8192 (tracker-store:22279): Tracker-INFO: 19:09:04.554: Setting cache size to 250 (tracker-store:22279): Tracker-INFO: 19:09:04.554: Loading databases files... (tracker-store:22279): Tracker-INFO: 19:09:04.554: Opened sqlite3 database:'/tmp/tracker-test-kbgjyxpt/cache/tracker/meta.db' (tracker-store:22279): Tracker-INFO: 19:09:04.555: Setting page size to 8192 (tracker-store:22279): Tracker-INFO: 19:09:04.555: Setting cache size to 250 (tracker-store:22279): Tracker-INFO: 19:09:04.555: Closed sqlite3 database:'/tmp/tracker-test-kbgjyxpt/cache/tracker/meta.db' (tracker-store:22279): Tracker-INFO: 19:09:04.582: Opened sqlite3 database:'/tmp/tracker-test-kbgjyxpt/cache/tracker/meta.db' (tracker-store:22279): Tracker-INFO: 19:09:04.582: Setting page size to 8192 (tracker-store:22279): Tracker-INFO: 19:09:04.604: Setting cache size to 250 (tracker-store:22279): Tracker-INFO: 19:09:05.671: Saving DB locale as: 'en_GB.utf8' (tracker-store:22279): Tracker-INFO: 19:09:05.673: Opened sqlite3 database:'/tmp/tracker-test-kbgjyxpt/cache/tracker/meta.db' (tracker-store:22279): Tracker-INFO: 19:09:05.711: Setting page size to 8192 (tracker-store:22279): Tracker-INFO: 19:09:05.711: Setting cache size to 250trackertestutils.dbusdaemon.stdout: dbus-daemon[23534]: [session uid=1000 pid=23534] The maximum number of pending replies for ":1.1" (uid=1000 pid=23543 comm="tests/functional-tests/ipc/test-bus-query-cancella" label="unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023") has been reached (max_replies_per_connection=128) Example after: (tracker-store:14505): Tracker-INFO: 19:03:50.256: Could not find database file:'/tmp/tracker-test-ask61juj/cache/tracker/meta.db', reindex will be forced (tracker-store:14505): Tracker-INFO: 19:03:50.257: Removing all files for database /tmp/tracker-test-ask61juj/cache/tracker/meta.db (tracker-store:14505): Tracker-INFO: 19:03:50.257: Creating database files for /tmp/tracker-test-ask61juj/cache/tracker/meta.db... (tracker-store:14505): Tracker-INFO: 19:03:50.298: Loading files for database /tmp/tracker-test-ask61juj/cache/tracker/meta.db... (tracker-store:14505): Tracker-INFO: 19:03:51.227: Saving DB locale as: 'en_GB.utf8' The size of the meson-logs/testlog.txt with TRACKER_VERBOSITY=1 reduces from 436KiB to 250KiB. We also now log a g_info() message when doing a blocking sqlite3_wal_checkpoint_v2() call. This may help with debugging the test timeouts that happen on certain CI runners (e.g. https://gitlab.gnome.org/GNOME/tracker/issues/145). --- src/libtracker-data/tracker-db-interface-sqlite.c | 10 +++++++-- src/libtracker-data/tracker-db-manager.c | 25 +++++++++-------------- 2 files changed, 18 insertions(+), 17 deletions(-) diff --git a/src/libtracker-data/tracker-db-interface-sqlite.c b/src/libtracker-data/tracker-db-interface-sqlite.c index a789fe963..9bbb7b64f 100644 --- a/src/libtracker-data/tracker-db-interface-sqlite.c +++ b/src/libtracker-data/tracker-db-interface-sqlite.c @@ -1933,7 +1933,7 @@ open_database (TrackerDBInterface *db_interface, "Could not open sqlite3 database:'%s': %s", db_interface->filename, str); return; } else { - g_info ("Opened sqlite3 database:'%s'", db_interface->filename); + g_debug ("Opened sqlite3 database:'%s'", db_interface->filename); } /* Set our unicode collation function */ @@ -2380,6 +2380,11 @@ tracker_db_interface_sqlite_wal_checkpoint (TrackerDBInterface *interface, GError **error) { int return_val; + GLogLevelFlags log_level; + + log_level = blocking ? G_LOG_LEVEL_INFO : G_LOG_LEVEL_DEBUG; + + g_log (G_LOG_DOMAIN, log_level, "Checkpointing database (%s)...", blocking ? "blocking" : "non-blocking"); return_val = sqlite3_wal_checkpoint_v2 (interface->db, NULL, blocking ? SQLITE_CHECKPOINT_FULL : SQLITE_CHECKPOINT_PASSIVE, @@ -2393,6 +2398,7 @@ tracker_db_interface_sqlite_wal_checkpoint (TrackerDBInterface *interface, return FALSE; } + g_log (G_LOG_DOMAIN, log_level, "Checkpointing complete"); return TRUE; } @@ -2406,7 +2412,7 @@ tracker_db_interface_sqlite_finalize (GObject *object) close_database (db_interface); g_free (db_interface->fts_properties); - g_info ("Closed sqlite3 database:'%s'", db_interface->filename); + g_debug ("Closed sqlite3 database:'%s'", db_interface->filename); g_free (db_interface->filename); diff --git a/src/libtracker-data/tracker-db-manager.c b/src/libtracker-data/tracker-db-manager.c index 03684bc95..4c03dc152 100644 --- a/src/libtracker-data/tracker-db-manager.c +++ b/src/libtracker-data/tracker-db-manager.c @@ -252,12 +252,12 @@ db_set_params (TrackerDBInterface *iface, tracker_db_interface_execute_query (iface, NULL, "PRAGMA \"%s\".journal_size_limit = 10240000", database); if (page_size != TRACKER_DB_PAGE_SIZE_DONT_SET) { - g_info (" Setting page size to %d", page_size); + g_debug (" Setting page size to %d", page_size); tracker_db_interface_execute_query (iface, NULL, "PRAGMA \"%s\".page_size = %d", database, page_size); } tracker_db_interface_execute_query (iface, NULL, "PRAGMA \"%s\".cache_size = %d", database, cache_size); - g_info (" Setting cache size to %d", cache_size); + g_debug (" Setting cache size to %d", cache_size); } void @@ -265,9 +265,8 @@ tracker_db_manager_remove_all (TrackerDBManager *db_manager) { gchar *filename; - g_info ("Removing all database/storage files"); + g_info ("Removing all files for database %s", db_manager->db.abs_filename); - g_info (" Removing database:'%s'", db_manager->db.abs_filename); g_unlink (db_manager->db.abs_filename); /* also delete shm and wal helper files */ @@ -499,12 +498,12 @@ db_recreate_all (TrackerDBManager *db_manager, * because at the time 'initialized' = FALSE and that * will cause errors and do nothing. */ - g_info ("Cleaning up database files for reindex"); + g_debug ("Cleaning up database files for reindex"); tracker_db_manager_remove_all (db_manager); /* Now create the databases and close them */ - g_info ("Creating database files, this may take a few moments..."); + g_info ("Creating database files for %s...", db_manager->db.abs_filename); db_manager->db.iface = tracker_db_manager_create_db_interface (db_manager, FALSE, &internal_error); if (internal_error) { @@ -611,7 +610,7 @@ tracker_db_manager_new (TrackerDBManagerFlags flags, need_reindex = FALSE; /* Set up locations */ - g_info ("Setting database locations"); + g_debug ("Setting database locations"); db_manager->flags = flags; db_manager->s_cache_size = select_cache_size; @@ -631,13 +630,13 @@ tracker_db_manager_new (TrackerDBManagerFlags flags, if ((flags & TRACKER_DB_MANAGER_READONLY) == 0) { /* Make sure the directories exist */ - g_info ("Checking database directories exist"); + g_debug ("Checking database directories exist"); g_mkdir_with_parents (db_manager->data_dir, 00755); g_mkdir_with_parents (db_manager->user_data_dir, 00755); } - g_info ("Checking whether database files exist"); + g_debug ("Checking whether database files exist"); /* Check we have the database in place, if it is * missing, we reindex. @@ -718,14 +717,14 @@ tracker_db_manager_new (TrackerDBManagerFlags flags, tracker_db_manager_update_version (db_manager); /* Load databases */ - g_info ("Loading databases files..."); + g_info ("Loading files for database %s...", db_manager->db.abs_filename); } else if ((flags & TRACKER_DB_MANAGER_READONLY) == 0) { /* do not do shutdown check for read-only mode (direct access) */ gboolean must_recreate = FALSE; /* Load databases */ - g_info ("Loading databases files..."); + g_info ("Loading files for database %s...", db_manager->db.abs_filename); if (!must_recreate && g_file_test (db_manager->in_use_filename, G_FILE_TEST_EXISTS)) { gsize size = 0; @@ -1123,8 +1122,6 @@ wal_checkpoint (TrackerDBInterface *iface, { GError *error = NULL; - g_debug ("Checkpointing database..."); - tracker_db_interface_sqlite_wal_checkpoint (iface, blocking, blocking ? &error : NULL); @@ -1134,8 +1131,6 @@ wal_checkpoint (TrackerDBInterface *iface, error->message); g_error_free (error); } - - g_debug ("Checkpointing complete"); } static gpointer -- cgit v1.2.1