Changeset: cc58b9d0e243 for MonetDB URL: https://dev.monetdb.org/hg/MonetDB/rev/cc58b9d0e243 Modified Files: gdk/gdk_logger.c gdk/gdk_logger_internals.h gdk/gdk_tracer.h sql/backends/monet5/sql_scenario.c Branch: Jun2023 Log Message:
Logging in the logger is now done through the tracer. It can still be enabled with sql_debug=1, but now also using the tracer interface using component "WAL". diffs (truncated from 479 to 300 lines): diff --git a/gdk/gdk_logger.c b/gdk/gdk_logger.c --- a/gdk/gdk_logger.c +++ b/gdk/gdk_logger.c @@ -350,8 +350,7 @@ log_read_updates(logger *lg, trans *tr, int tpe; assert(!lg->inmemory); - if (lg->debug & 1) - fprintf(stderr, "#logger found log_read_updates %d %s\n", id, l->flag == LOG_UPDATE ? "update" : "update_buld"); + TRC_DEBUG(WAL, "found %d %s", id, l->flag == LOG_UPDATE ? "update" : "update_buld"); if (mnstr_readLng(lg->input_log, &nr) != 1 || mnstr_read(lg->input_log, &type_id, 1, 1) != 1) @@ -769,8 +768,7 @@ log_read_create(logger *lg, trans *tr, l int tpe; assert(!lg->inmemory); - if (lg->debug & 1) - fprintf(stderr, "#log_read_create %d\n", id); + TRC_DEBUG(WAL, "create %d", id); if (mnstr_read(lg->input_log, &tt, 1, 1) != 1) return LOG_ERR; @@ -927,8 +925,9 @@ tr_abort_(logger *lg, trans *tr, int s) { int i; - if (lg->debug & 1) - fprintf(stderr, "#tr_abort\n"); + (void) lg; + + TRC_DEBUG(WAL, "abort"); for (i = s; i < tr->nr; i++) la_destroy(&tr->changes[i]); @@ -946,8 +945,7 @@ tr_commit(logger *lg, trans *tr) { int i; - if (lg->debug & 1) - fprintf(stderr, "#tr_commit\n"); + TRC_DEBUG(WAL, "commit"); for (i = 0; i < tr->nr; i++) { if (la_apply(lg, &tr->changes[i], tr->tid) != GDK_SUCCEED) { @@ -1061,8 +1059,7 @@ log_open_output(logger *lg) return GDK_FAIL; } - if (lg->debug & 1) - fprintf(stderr, "#log_open_output: %s.%s\n", LOGFILE, id); + TRC_DEBUG(WAL, "opening %s.%s", LOGFILE, id); new_range->output_log = open_wstream(filename); if (new_range->output_log) { short byteorder = 1234; @@ -1095,22 +1092,27 @@ log_open_output(logger *lg) static inline void log_close_input(logger *lg) { - if (!lg->inmemory) + if (!lg->inmemory && lg->input_log) { + TRC_DEBUG(WAL, "closing input log %s", mnstr_name(lg->input_log)); close_stream(lg->input_log); + } lg->input_log = NULL; } static inline void log_close_output(logger *lg) { - if (!LOG_DISABLED(lg)) + if (!LOG_DISABLED(lg) && lg->current->output_log) { + TRC_DEBUG(WAL, "closing output log %s", mnstr_name(lg->current->output_log)); close_stream(lg->current->output_log); + } lg->current->output_log = NULL; } static gdk_return -log_open_input(logger *lg, char *filename, bool *filemissing) +log_open_input(logger *lg, const char *filename, bool *filemissing) { + TRC_DEBUG(WAL, "opening input log %s", filename); lg->input_log = open_rstream(filename); /* if the file doesn't exist, there is nothing to be read back */ @@ -1160,15 +1162,13 @@ log_read_transaction(logger *lg) break; } - if (lg->debug & 1) { - fprintf(stderr, "#log_readlog: "); + TRC_DEBUG_IF(WAL) { if (l.flag > 0 && l.flag != LOG_CLEAR && l.flag < (bte) (sizeof(log_commands) / sizeof(log_commands[0]))) - fprintf(stderr, "%s", log_commands[(int) l.flag]); + TRC_DEBUG_ENDIF(WAL, "%s %d", log_commands[(int) l.flag], l.id); else - fprintf(stderr, "%d", l.flag); - fprintf(stderr, " %d\n", l.id); + TRC_DEBUG_ENDIF(WAL, "%d %d", l.flag, l.id); } /* the functions we call here can succeed (LOG_OK), * but they can also fail for two different reasons: @@ -1186,8 +1186,7 @@ log_read_transaction(logger *lg) err = LOG_ERR; break; } - if (lg->debug & 1) - fprintf(stderr, "#logger tstart %d\n", tr->tid); + TRC_DEBUG(WAL, "tstart %d\n", tr->tid); break; case LOG_END: if (tr == NULL) @@ -1262,7 +1261,7 @@ log_read_transaction(logger *lg) } static gdk_return -log_readlog(logger *lg, char *filename, bool *filemissing) +log_readlog(logger *lg, const char *filename, bool *filemissing) { log_return err = LOG_OK; time_t t0, t1; @@ -1270,27 +1269,23 @@ log_readlog(logger *lg, char *filename, assert(!lg->inmemory); - if (lg->debug & 1) { - fprintf(stderr, "#log_readlog opening %s\n", filename); - } + TRC_DEBUG(WAL, "opening %s\n", filename); gdk_return res = log_open_input(lg, filename, filemissing); if (!lg->input_log || res != GDK_SUCCEED) return res; int fd; if ((fd = getFileNo(lg->input_log)) < 0 || fstat(fd, &sb) < 0) { - if (lg->debug & 1) { - fprintf(stderr, "!ERROR: log_readlog: fstat on opened file %s failed\n", filename); - } + GDKsyserror("fstat on opened file %s failed\n", filename); log_close_input(lg); /* If the file could be opened, but fstat fails, * something weird is going on */ return GDK_FAIL; } t0 = time(NULL); - if (lg->debug & 1) { - printf("# Start reading the write-ahead log '%s'\n", filename); - fflush(stdout); + TRC_DEBUG_IF(WAL) { + TRC_DEBUG_ENDIF(WAL, "Start reading the write-ahead log '%s'\n", filename); + GDKtracer_flush_buffer(); } while (err != LOG_EOF && err != LOG_ERR) { t1 = time(NULL); @@ -1299,9 +1294,11 @@ log_readlog(logger *lg, char *filename, t0 = t1; /* not more than once every 10 seconds */ fpos = (lng) getfilepos(getFile(lg->input_log)); - if (lg->debug & 1 && fpos >= 0) { - printf("# still reading write-ahead log \"%s\" (%d%% done)\n", filename, (int) ((fpos * 100 + 50) / sb.st_size)); - fflush(stdout); + TRC_DEBUG_IF(WAL) { + if (fpos >= 0) { + TRC_DEBUG_ENDIF(WAL, "still reading write-ahead log \"%s\" (%d%% done)\n", filename, (int) ((fpos * 100 + 50) / sb.st_size)); + GDKtracer_flush_buffer(); + } } } err = log_read_transaction(lg); @@ -1310,9 +1307,9 @@ log_readlog(logger *lg, char *filename, lg->input_log = NULL; /* remaining transactions are not committed, ie abort */ - if (lg->debug & 1) { - printf("# Finished reading the write-ahead log '%s'\n", filename); - fflush(stdout); + TRC_DEBUG_IF(WAL) { + TRC_DEBUG_ENDIF(WAL, "Finished reading the write-ahead log '%s'\n", filename); + GDKtracer_flush_buffer(); } /* we cannot distinguish errors from incomplete transactions * (even if we would log aborts in the logs). So we simply @@ -1326,13 +1323,12 @@ log_readlog(logger *lg, char *filename, * processed in the same sequence. */ static gdk_return -log_readlogs(logger *lg, char *filename) +log_readlogs(logger *lg, const char *filename) { gdk_return res = GDK_SUCCEED; assert(!lg->inmemory); - if (lg->debug & 1) - fprintf(stderr, "#log_readlogs logger id is " LLFMT " last logger id is " LLFMT "\n", lg->id, lg->saved_id); + TRC_DEBUG(WAL, "logger id is " LLFMT " last logger id is " LLFMT "\n", lg->id, lg->saved_id); char log_filename[FILENAME_MAX]; if (lg->saved_id >= lg->id) { @@ -1357,8 +1353,7 @@ log_readlogs(logger *lg, char *filename) static gdk_return log_commit(logger *lg) { - if (lg->debug & 1) - fprintf(stderr, "#log_commit\n"); + TRC_DEBUG(WAL, "commit"); return bm_commit(lg); } @@ -1660,8 +1655,7 @@ bm_subcommit(logger *lg) if (lids && lids[p] != lng_nil && lids[p] <= lg->saved_tid) cleanup++; - if (lg->debug & 1) - fprintf(stderr, "#commit new %s (%d)\n", BBP_logical(col), col); + TRC_DEBUG(WAL, "new %s (%d)\n", BBP_logical(col), col); assert(col); sizes[i] = cnts?(BUN)cnts[p]:0; n[i++] = col; @@ -1764,17 +1758,16 @@ bm_subcommit(logger *lg) assert((BUN) i <= nn); log_unlock(lg); - if (lg->debug & 1) + TRC_DEBUG_IF(WAL) t0 = GDKusec(); res = TMsubcommit_list(n, cnts?sizes:NULL, i, lg->saved_id, lg->saved_tid); - if (lg->debug & 1) - fprintf(stderr, "#subcommit " LLFMT "usec\n", GDKusec() - t0); + TRC_DEBUG(WAL, "subcommit " LLFMT "usec\n", GDKusec() - t0); if (res == GDK_SUCCEED) { /* now cleanup */ - for(i=0;i<rcnt; i++) { - if (lg->debug & 1) { - fprintf(stderr, "#release %d\n", r[i]); + for (i = 0; i < rcnt; i++) { + TRC_DEBUG_IF(WAL) { + TRC_DEBUG_ENDIF(WAL, "release %d\n", r[i]); if (BBP_lrefs(r[i]) != 2) - fprintf(stderr, "#release %d %d\n", r[i], BBP_lrefs(r[i])); + TRC_DEBUG_ENDIF(WAL, "release %d %d\n", r[i], BBP_lrefs(r[i])); } BBPrelease(r[i]); } @@ -1831,7 +1824,7 @@ log_cleanup(logger *lg, lng id) * unless running in read-only mode * Load data and persist it in the BATs */ static gdk_return -log_load(int debug, const char *fn, const char *logdir, logger *lg, char filename[FILENAME_MAX]) +log_load(const char *fn, const char *logdir, logger *lg, char filename[FILENAME_MAX]) { FILE *fp = NULL; char bak[FILENAME_MAX]; @@ -1909,8 +1902,7 @@ log_load(int debug, const char *fn, cons (lg->dcatalog = BATsetaccess(lg->dcatalog, BAT_READ)) == NULL) { goto error; } - if (debug & 1) - fprintf(stderr, "#create %s catalog\n", fn); + TRC_DEBUG(WAL, "create %s catalog\n", fn); /* give the catalog bats names so we can find them * next time */ @@ -2195,9 +2187,7 @@ log_new(int debug, const char *fn, const GDKfree(lg); return NULL; } - if (lg->debug & 1) { - fprintf(stderr, "#log_new dir set to %s\n", lg->dir); - } + TRC_DEBUG(WAL, "dir set to %s\n", lg->dir); MT_lock_init(&lg->lock, fn); MT_lock_init(&lg->rotation_lock, "rotation_lock"); @@ -2205,7 +2195,7 @@ log_new(int debug, const char *fn, const MT_cond_init(&lg->excl_flush_cv); ATOMIC_INIT(&lg->nr_flushers, 0); - if (log_load(debug, fn, logdir, lg, filename) == GDK_SUCCEED) { + if (log_load(fn, logdir, lg, filename) == GDK_SUCCEED) { return lg; } return NULL; @@ -2234,7 +2224,8 @@ do_flush_range_cleanup(logger* lg) { for (frange = first; frange && frange != flast; frange = frange->next) { ATOMIC_DEC(&frange->refcount); - if (!LOG_DISABLED(lg)) { + if (!LOG_DISABLED(lg) && frange->output_log) { + TRC_DEBUG(WAL, "closing output log %s", mnstr_name(frange->output_log)); close_stream(frange->output_log); frange->output_log = NULL; } @@ -2307,16 +2298,16 @@ logger * log_create(int debug, const char *fn, const char *logdir, int version, preversionfix_fptr prefuncp, postversionfix_fptr postfuncp, void *funcdata) { logger *lg; + TRC_DEBUG_IF(WAL) { + TRC_DEBUG_ENDIF(WAL, "Started processing logs %s/%s version %d\n", fn, logdir, version); _______________________________________________ checkin-list mailing list -- checkin-list@monetdb.org To unsubscribe send an email to checkin-list-le...@monetdb.org