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 -- [email protected]
To unsubscribe send an email to [email protected]
