From: Kern Sibbald Date: Wed, 3 Mar 2004 09:10:52 +0000 (+0000) Subject: Improve debug output scheduler+jobq+tracing X-Git-Tag: Release-7.0.0~9648 X-Git-Url: https://git.sur5r.net/?a=commitdiff_plain;h=f4970fe5b18a99f1981eb67d743faf6eedceb7f2;p=bacula%2Fbacula Improve debug output scheduler+jobq+tracing git-svn-id: https://bacula.svn.sourceforge.net/svnroot/bacula/trunk@1105 91ce42f0-d328-0410-95d8-f526ca767f89 --- diff --git a/bacula/src/cats/sql.c b/bacula/src/cats/sql.c index 79dc10c5d9..58d331037b 100644 --- a/bacula/src/cats/sql.c +++ b/bacula/src/cats/sql.c @@ -52,16 +52,16 @@ static int int_handler(void *ctx, int num_fields, char **row) { uint32_t *val = (uint32_t *)ctx; - Dmsg1(50, "int_handler starts with row pointing at %x\n", row); + Dmsg1(200, "int_handler starts with row pointing at %x\n", row); if (row[0]) { - Dmsg1(50, "int_handler finds '%s'\n", row[0]); + Dmsg1(200, "int_handler finds '%s'\n", row[0]); *val = atoi(row[0]); } else { - Dmsg0(50, "int_handler finds zero\n"); + Dmsg0(200, "int_handler finds zero\n"); *val = 0; } - Dmsg0(50, "int_handler finishes\n"); + Dmsg0(200, "int_handler finishes\n"); return 0; } @@ -383,17 +383,17 @@ list_result(JCR *jcr, B_DB *mdb, DB_LIST_HANDLER *send, void *ctx, e_list_type t int i, col_len, max_len = 0; char buf[2000], ewc[30]; - Dmsg0(50, "list_result starts\n"); + Dmsg0(200, "list_result starts\n"); if (mdb->result == NULL || sql_num_rows(mdb) == 0) { send(ctx, _("No results to list.\n")); return; } - Dmsg1(50, "list_result starts looking at %d fields\n", sql_num_fields(mdb)); + Dmsg1(200, "list_result starts looking at %d fields\n", sql_num_fields(mdb)); /* determine column display widths */ sql_field_seek(mdb, 0); for (i = 0; i < sql_num_fields(mdb); i++) { - Dmsg1(50, "list_result processing field %d\n", i); + Dmsg1(200, "list_result processing field %d\n", i); field = sql_fetch_field(mdb); col_len = strlen(field->name); if (type == VERT_LIST) { @@ -414,17 +414,17 @@ list_result(JCR *jcr, B_DB *mdb, DB_LIST_HANDLER *send, void *ctx, e_list_type t } } - Dmsg0(50, "list_result finished first loop\n"); + Dmsg0(200, "list_result finished first loop\n"); if (type == VERT_LIST) { goto vertical_list; } - Dmsg1(50, "list_result starts second loop looking at %d fields\n", sql_num_fields(mdb)); + Dmsg1(200, "list_result starts second loop looking at %d fields\n", sql_num_fields(mdb)); list_dashes(mdb, send, ctx); send(ctx, "|"); sql_field_seek(mdb, 0); for (i = 0; i < sql_num_fields(mdb); i++) { - Dmsg1(50, "list_result looking at field %d\n", i); + Dmsg1(200, "list_result looking at field %d\n", i); field = sql_fetch_field(mdb); bsnprintf(buf, sizeof(buf), " %-*s |", (int)field->max_length, field->name); send(ctx, buf); @@ -432,7 +432,7 @@ list_result(JCR *jcr, B_DB *mdb, DB_LIST_HANDLER *send, void *ctx, e_list_type t send(ctx, "\n"); list_dashes(mdb, send, ctx); - Dmsg1(50, "list_result starts third loop looking at %d fields\n", sql_num_fields(mdb)); + Dmsg1(200, "list_result starts third loop looking at %d fields\n", sql_num_fields(mdb)); while ((row = sql_fetch_row(mdb)) != NULL) { sql_field_seek(mdb, 0); send(ctx, "|"); @@ -455,7 +455,7 @@ list_result(JCR *jcr, B_DB *mdb, DB_LIST_HANDLER *send, void *ctx, e_list_type t vertical_list: - Dmsg1(50, "list_result starts vertical list at %d fields\n", sql_num_fields(mdb)); + Dmsg1(200, "list_result starts vertical list at %d fields\n", sql_num_fields(mdb)); while ((row = sql_fetch_row(mdb)) != NULL) { sql_field_seek(mdb, 0); for (i = 0; i < sql_num_fields(mdb); i++) { diff --git a/bacula/src/console/Makefile.in b/bacula/src/console/Makefile.in index ba266f27d4..860ac0bd1b 100644 --- a/bacula/src/console/Makefile.in +++ b/bacula/src/console/Makefile.in @@ -3,9 +3,9 @@ # @MCOMMON@ -srcdir = . -VPATH = . -.PATH: . +srcdir = . +VPATH = . +.PATH: . # one up basedir = .. @@ -30,74 +30,74 @@ CONS_INC=@CONS_INC@ CONS_LIBS=@CONS_LIBS@ CONS_LDFLAGS=@CONS_LDFLAGS@ -.SUFFIXES: .c .o +.SUFFIXES: .c .o .PHONY: .DONTCARE: # inference rules .c.o: - $(CXX) $(DEFS) $(DEBUG) -c $(CPPFLAGS) $(CONS_INC) -I$(srcdir) -I$(basedir) $(DINCLUDE) $(CFLAGS) $< + $(CXX) $(DEFS) $(DEBUG) -c $(CPPFLAGS) $(CONS_INC) -I$(srcdir) -I$(basedir) $(DINCLUDE) $(CFLAGS) $< #------------------------------------------------------------------------- all: Makefile bconsole @STATIC_CONS@ - @echo "==== Make of console is good ====" - @echo " " + @echo "==== Make of console is good ====" + @echo " " bconsole: $(CONSOBJS) ../lib/libbac.a ../cats/libsql.a - $(CXX) $(LDFLAGS) $(CONS_LDFLAGS) -L../lib -L../cats -o $@ $(CONSOBJS) \ - $(LIBS) $(DLIB) $(CONS_LIBS) -lbac -lsql -lm + $(CXX) $(LDFLAGS) $(CONS_LDFLAGS) -L../lib -L../cats -o $@ $(CONSOBJS) \ + $(LIBS) $(DLIB) $(CONS_LIBS) -lbac -lsql -lm static-bconsole: $(CONSOBJS) ../lib/libbac.a ../cats/libsql.a - $(CXX) -static $(LDFLAGS) $(CONS_LDFLAGS) -L../lib -L../cats -o $@ $(CONSOBJS) \ - $(LIBS) $(DLIB) $(CONS_LIBS) -lbac -lsql -lm - strip $@ + $(CXX) -static $(LDFLAGS) $(CONS_LDFLAGS) -L../lib -L../cats -o $@ $(CONSOBJS) \ + $(LIBS) $(DLIB) $(CONS_LIBS) -lbac -lsql -lm + strip $@ Makefile: $(srcdir)/Makefile.in $(topdir)/config.status - cd $(topdir) \ - && CONFIG_FILES=$(thisdir)/$@ CONFIG_HEADERS= $(SHELL) ./config.status + cd $(topdir) \ + && CONFIG_FILES=$(thisdir)/$@ CONFIG_HEADERS= $(SHELL) ./config.status clean: - @$(RMF) console bconsole core core.* a.out *.o *.bak *~ *.intpro *.extpro 1 2 3 - @$(RMF) static-console static-bconsole gmon.out + @$(RMF) console bconsole core core.* a.out *.o *.bak *~ *.intpro *.extpro 1 2 3 + @$(RMF) static-console static-bconsole gmon.out realclean: clean - @$(RMF) tags console.conf bconsole.conf + @$(RMF) tags console.conf bconsole.conf distclean: realclean - if test $(srcdir) = .; then $(MAKE) realclean; fi - (cd $(srcdir); $(RMF) Makefile; $(RMF) -r CVS) + if test $(srcdir) = .; then $(MAKE) realclean; fi + (cd $(srcdir); $(RMF) Makefile; $(RMF) -r CVS) install: all - @if test -f ${DESTDIR}${sbindir}/console; then \ - echo " "; \ - echo "Warning!!! ${DESTDIR}${sbindir}console found."; \ - echo " console has been renamed bconsole, so console"; \ - echo " is no longer used, and you might want to delete it."; \ - echo " "; \ - fi - $(INSTALL_PROGRAM) bconsole $(DESTDIR)$(sbindir)/bconsole - @srcconf=bconsole.conf; \ - if test -f ${DESTDIR}${sysconfdir}/$$srcconf; then \ - destconf=$$srcconf.new; \ - echo " ==> Found existing $$srcconf, installing new conf file as $$destconf"; \ - else \ - destconf=$$srcconf; \ - if test -f ${DESTDIR}${sysconfdir}/console.conf; then \ - echo "Existing console.conf moved to bconsole.conf"; \ - @$(MV) ${DESTDIR}${sysconfdir}/console.conf ${DESTDIR}${sysconfdir}/bconsole.conf; \ - destconf=$$srcconf.new; \ - fi; \ - fi; \ - echo "${INSTALL_CONFIG} $$srcconf ${DESTDIR}${sysconfdir}/$$destconf"; \ - ${INSTALL_CONFIG} $$srcconf ${DESTDIR}${sysconfdir}/$$destconf - if test -f static-bconsole; then \ - $(INSTALL_PROGRAM) static-bconsole $(DESTDIR)$(sbindir)/static-bconsole; \ - fi + @if test -f ${DESTDIR}${sbindir}/console; then \ + echo " "; \ + echo "Warning!!! ${DESTDIR}${sbindir}console found."; \ + echo " console has been renamed bconsole, so console"; \ + echo " is no longer used, and you might want to delete it."; \ + echo " "; \ + fi + $(INSTALL_PROGRAM) bconsole $(DESTDIR)$(sbindir)/bconsole + @srcconf=bconsole.conf; \ + if test -f ${DESTDIR}${sysconfdir}/$$srcconf; then \ + destconf=$$srcconf.new; \ + echo " ==> Found existing $$srcconf, installing new conf file as $$destconf"; \ + else \ + destconf=$$srcconf; \ + if test -f ${DESTDIR}${sysconfdir}/console.conf; then \ + echo "Existing console.conf moved to bconsole.conf"; \ + @$(MV) ${DESTDIR}${sysconfdir}/console.conf ${DESTDIR}${sysconfdir}/bconsole.conf; \ + destconf=$$srcconf.new; \ + fi; \ + fi; \ + echo "${INSTALL_CONFIG} $$srcconf ${DESTDIR}${sysconfdir}/$$destconf"; \ + ${INSTALL_CONFIG} $$srcconf ${DESTDIR}${sysconfdir}/$$destconf + if test -f static-bconsole; then \ + $(INSTALL_PROGRAM) static-bconsole $(DESTDIR)$(sbindir)/static-bconsole; \ + fi uninstall: - (cd $(DESTDIR)$(sbindir); $(RMF) bconsole static-bconsole) - (cd $(DESTDIR)$(sysconfdir); $(RMF) console.conf bconsole.conf bconsole.conf.new) + (cd $(DESTDIR)$(sbindir); $(RMF) bconsole static-bconsole) + (cd $(DESTDIR)$(sysconfdir); $(RMF) console.conf bconsole.conf bconsole.conf.new) @@ -107,16 +107,16 @@ uninstall: # `semi'-automatic since dependencies are generated at distribution time. depend: - @$(MV) Makefile Makefile.bak - @$(SED) "/^# DO NOT DELETE:/,$$ d" Makefile.bak > Makefile - @$(ECHO) "# DO NOT DELETE: nice dependency list follows" >> Makefile - @$(CC) -S -M $(CPPFLAGS) $(CONS_INC) -I$(srcdir) -I$(basedir) $(SQL_INC) *.c >> Makefile - @if test -f Makefile ; then \ - $(RMF) Makefile.bak; \ - else \ - $(MV) Makefile.bak Makefile; \ - echo -e "Something went wrong\n\a"; \ - fi + @$(MV) Makefile Makefile.bak + @$(SED) "/^# DO NOT DELETE:/,$$ d" Makefile.bak > Makefile + @$(ECHO) "# DO NOT DELETE: nice dependency list follows" >> Makefile + @$(CC) -S -M $(CPPFLAGS) $(CONS_INC) -I$(srcdir) -I$(basedir) $(SQL_INC) *.c >> Makefile + @if test -f Makefile ; then \ + $(RMF) Makefile.bak; \ + else \ + $(MV) Makefile.bak Makefile; \ + echo -e "Something went wrong\n\a"; \ + fi # ----------------------------------------------------------------------- # DO NOT DELETE: nice dependency list follows diff --git a/bacula/src/dird/jobq.c b/bacula/src/dird/jobq.c index c283871b8f..abd65e2482 100755 --- a/bacula/src/dird/jobq.c +++ b/bacula/src/dird/jobq.c @@ -57,6 +57,7 @@ int jobq_init(jobq_t *jq, int threads, void *(*engine)(void *arg)) jobq_item_t *item = NULL; if ((stat = pthread_attr_init(&jq->attr)) != 0) { + Jmsg1(NULL, M_ERROR, 0, "pthread_attr_init: ERR=%s\n", strerror(stat)); return stat; } if ((stat = pthread_attr_setdetachstate(&jq->attr, PTHREAD_CREATE_DETACHED)) != 0) { @@ -64,10 +65,12 @@ int jobq_init(jobq_t *jq, int threads, void *(*engine)(void *arg)) return stat; } if ((stat = pthread_mutex_init(&jq->mutex, NULL)) != 0) { + Jmsg1(NULL, M_ERROR, 0, "pthread_mutex_init: ERR=%s\n", strerror(stat)); pthread_attr_destroy(&jq->attr); return stat; } if ((stat = pthread_cond_init(&jq->work, NULL)) != 0) { + Jmsg1(NULL, M_ERROR, 0, "pthread_cond_init: ERR=%s\n", strerror(stat)); pthread_mutex_destroy(&jq->mutex); pthread_attr_destroy(&jq->attr); return stat; @@ -99,6 +102,7 @@ int jobq_destroy(jobq_t *jq) return EINVAL; } if ((stat = pthread_mutex_lock(&jq->mutex)) != 0) { + Jmsg1(NULL, M_ERROR, 0, "pthread_mutex_lock: ERR=%s\n", strerror(stat)); return stat; } jq->valid = 0; /* prevent any more operations */ @@ -110,18 +114,21 @@ int jobq_destroy(jobq_t *jq) jq->quit = true; if (jq->idle_workers) { if ((stat = pthread_cond_broadcast(&jq->work)) != 0) { + Jmsg1(NULL, M_ERROR, 0, "pthread_cond_broadcast: ERR=%s\n", strerror(stat)); pthread_mutex_unlock(&jq->mutex); return stat; } } while (jq->num_workers > 0) { if ((stat = pthread_cond_wait(&jq->work, &jq->mutex)) != 0) { + Jmsg1(NULL, M_ERROR, 0, "pthread_cond_wait: ERR=%s\n", strerror(stat)); pthread_mutex_unlock(&jq->mutex); return stat; } } } if ((stat = pthread_mutex_unlock(&jq->mutex)) != 0) { + Jmsg1(NULL, M_ERROR, 0, "pthread_mutex_unlock: ERR=%s\n", strerror(stat)); return stat; } stat = pthread_mutex_destroy(&jq->mutex); @@ -150,7 +157,7 @@ static void *sched_wait(void *arg) JCR *jcr = ((wait_pkt *)arg)->jcr; jobq_t *jq = ((wait_pkt *)arg)->jq; - Dmsg0(100, "Enter sched_wait.\n"); + Dmsg0(010, "Enter sched_wait.\n"); free(arg); time_t wtime = jcr->sched_time - time(NULL); /* Wait until scheduled time arrives */ @@ -161,7 +168,7 @@ static void *sched_wait(void *arg) } /* Check every 30 seconds if canceled */ while (wtime > 0) { - Dmsg2(100, "Waiting on sched time, jobid=%d secs=%d\n", jcr->JobId, wtime); + Dmsg2(010, "Waiting on sched time, jobid=%d secs=%d\n", jcr->JobId, wtime); if (wtime > 30) { wtime = 30; } @@ -175,7 +182,7 @@ static void *sched_wait(void *arg) jobq_add(jq, jcr); V(jcr->mutex); free_jcr(jcr); /* we are done with jcr */ - Dmsg0(100, "Exit sched_wait\n"); + Dmsg0(010, "Exit sched_wait\n"); return NULL; } @@ -196,14 +203,15 @@ int jobq_add(jobq_t *jq, JCR *jcr) pthread_t id; wait_pkt *sched_pkt; - + Dmsg3(000, "jobq_add jobid=%d jcr=0x%x use_count=%d\n", jcr->JobId, jcr, jcr->use_count); if (jq->valid != JOBQ_VALID) { + Jmsg0(jcr, M_ERROR, 0, "Jobq_add queue not initialized.\n"); return EINVAL; } jcr->use_count++; /* mark jcr in use by us */ - Dmsg3(100, "jobq_add jobid=%d jcr=0x%x use_count=%d\n", jcr->JobId, jcr, jcr->use_count); + Dmsg3(010, "jobq_add jobid=%d jcr=0x%x use_count=%d\n", jcr->JobId, jcr, jcr->use_count); if (!job_canceled(jcr) && wtime > 0) { set_thread_concurrency(jq->max_workers + 2); sched_pkt = (wait_pkt *)malloc(sizeof(wait_pkt)); @@ -211,12 +219,14 @@ int jobq_add(jobq_t *jq, JCR *jcr) sched_pkt->jq = jq; stat = pthread_create(&id, &jq->attr, sched_wait, (void *)sched_pkt); if (stat != 0) { /* thread not created */ + Jmsg1(jcr, M_ERROR, 0, "pthread_thread_create: ERR=%s\n", strerror(stat)); jcr->use_count--; /* release jcr */ } return stat; } if ((stat = pthread_mutex_lock(&jq->mutex)) != 0) { + Jmsg1(jcr, M_ERROR, 0, "pthread_mutex_lock: ERR=%s\n", strerror(stat)); jcr->use_count--; /* release jcr */ return stat; } @@ -230,15 +240,15 @@ int jobq_add(jobq_t *jq, JCR *jcr) if (job_canceled(jcr)) { /* Add job to ready queue so that it is canceled quickly */ jq->ready_jobs->prepend(item); - Dmsg1(100, "Prepended job=%d to ready queue\n", jcr->JobId); + Dmsg1(010, "Prepended job=%d to ready queue\n", jcr->JobId); } else { /* Add this job to the wait queue in priority sorted order */ foreach_dlist(li, jq->waiting_jobs) { - Dmsg2(100, "waiting item jobid=%d priority=%d\n", + Dmsg2(010, "waiting item jobid=%d priority=%d\n", li->jcr->JobId, li->jcr->JobPriority); if (li->jcr->JobPriority > jcr->JobPriority) { jq->waiting_jobs->insert_before(item, li); - Dmsg2(100, "insert_before jobid=%d before %d\n", + Dmsg2(010, "insert_before jobid=%d before waiting job=%d\n", li->jcr->JobId, jcr->JobId); inserted = true; break; @@ -247,7 +257,7 @@ int jobq_add(jobq_t *jq, JCR *jcr) /* If not jobs in wait queue, append it */ if (!inserted) { jq->waiting_jobs->append(item); - Dmsg1(100, "Appended item jobid=%d\n", jcr->JobId); + Dmsg1(010, "Appended item jobid=%d to waiting queue\n", jcr->JobId); } } @@ -255,7 +265,7 @@ int jobq_add(jobq_t *jq, JCR *jcr) stat = start_server(jq); pthread_mutex_unlock(&jq->mutex); - Dmsg0(100, "Return jobq_add\n"); + Dmsg0(010, "Return jobq_add\n"); return stat; } @@ -274,12 +284,13 @@ int jobq_remove(jobq_t *jq, JCR *jcr) bool found = false; jobq_item_t *item; - Dmsg2(100, "jobq_remove jobid=%d jcr=0x%x\n", jcr->JobId, jcr); + Dmsg2(010, "jobq_remove jobid=%d jcr=0x%x\n", jcr->JobId, jcr); if (jq->valid != JOBQ_VALID) { return EINVAL; } if ((stat = pthread_mutex_lock(&jq->mutex)) != 0) { + Jmsg1(NULL, M_ERROR, 0, "pthread_mutex_lock: ERR=%s\n", strerror(stat)); return stat; } @@ -291,19 +302,19 @@ int jobq_remove(jobq_t *jq, JCR *jcr) } if (!found) { pthread_mutex_unlock(&jq->mutex); - Dmsg2(100, "jobq_remove jobid=%d jcr=0x%x not in wait queue\n", jcr->JobId, jcr); + Dmsg2(010, "jobq_remove jobid=%d jcr=0x%x not in wait queue\n", jcr->JobId, jcr); return EINVAL; } /* Move item to be the first on the list */ jq->waiting_jobs->remove(item); jq->ready_jobs->prepend(item); - Dmsg2(100, "jobq_remove jobid=%d jcr=0x%x moved to ready queue\n", jcr->JobId, jcr); + Dmsg2(010, "jobq_remove jobid=%d jcr=0x%x moved to ready queue\n", jcr->JobId, jcr); stat = start_server(jq); pthread_mutex_unlock(&jq->mutex); - Dmsg0(100, "Return jobq_remove\n"); + Dmsg0(010, "Return jobq_remove\n"); return stat; } @@ -318,15 +329,17 @@ static int start_server(jobq_t *jq) /* if any threads are idle, wake one */ if (jq->idle_workers > 0) { - Dmsg0(100, "Signal worker to wake up\n"); + Dmsg0(010, "Signal worker to wake up\n"); if ((stat = pthread_cond_signal(&jq->work)) != 0) { + Jmsg1(NULL, M_ERROR, 0, "pthread_cond_signal: ERR=%s\n", strerror(stat)); return stat; } } else if (jq->num_workers < jq->max_workers) { - Dmsg0(100, "Create worker thread\n"); + Dmsg0(010, "Create worker thread\n"); /* No idle threads so create a new one */ set_thread_concurrency(jq->max_workers + 1); if ((stat = pthread_create(&id, &jq->attr, jobq_server, (void *)jq)) != 0) { + Jmsg1(NULL, M_ERROR, 0, "pthread_create: ERR=%s\n", strerror(stat)); return stat; } } @@ -348,8 +361,9 @@ static void *jobq_server(void *arg) bool timedout; bool work = true; - Dmsg0(100, "Start jobq_server\n"); + Dmsg0(010, "Start jobq_server\n"); if ((stat = pthread_mutex_lock(&jq->mutex)) != 0) { + Jmsg1(NULL, M_ERROR, 0, "pthread_mutex_lock: ERR=%s\n", strerror(stat)); return NULL; } jq->num_workers++; @@ -358,9 +372,8 @@ static void *jobq_server(void *arg) struct timeval tv; struct timezone tz; - Dmsg0(100, "Top of for loop\n"); + Dmsg0(010, "Top of for loop\n"); timedout = false; - Dmsg0(100, "gettimeofday()\n"); gettimeofday(&tv, &tz); timeout.tv_nsec = 0; timeout.tv_sec = tv.tv_sec + 4; @@ -369,31 +382,32 @@ static void *jobq_server(void *arg) /* * Wait 4 seconds, then if no more work, exit */ - Dmsg0(200, "pthread_cond_timedwait()\n"); + Dmsg0(010, "pthread_cond_timedwait()\n"); stat = pthread_cond_timedwait(&jq->work, &jq->mutex, &timeout); - Dmsg1(100, "timedwait=%d\n", stat); if (stat == ETIMEDOUT) { + Dmsg0(010, "timedwait timedout.\n"); timedout = true; break; } else if (stat != 0) { /* This shouldn't happen */ - Dmsg0(100, "This shouldn't happen\n"); + Dmsg0(010, "This shouldn't happen\n"); jq->num_workers--; pthread_mutex_unlock(&jq->mutex); return NULL; } + break; } /* * If anything is in the ready queue, run it */ - Dmsg0(100, "Checking ready queue.\n"); + Dmsg0(010, "Checking ready queue.\n"); while (!jq->ready_jobs->empty() && !jq->quit) { JCR *jcr; je = (jobq_item_t *)jq->ready_jobs->first(); jcr = je->jcr; jq->ready_jobs->remove(je); if (!jq->ready_jobs->empty()) { - Dmsg0(100, "ready queue not empty start server\n"); + Dmsg0(010, "ready queue not empty start server\n"); if (start_server(jq) != 0) { jq->num_workers--; pthread_mutex_unlock(&jq->mutex); @@ -401,21 +415,23 @@ static void *jobq_server(void *arg) } } jq->running_jobs->append(je); - Dmsg1(100, "Took jobid=%d from ready and appended to run\n", jcr->JobId); + Dmsg1(010, "Took jobid=%d from ready and appended to run\n", jcr->JobId); if ((stat = pthread_mutex_unlock(&jq->mutex)) != 0) { + Jmsg1(NULL, M_ERROR, 0, "pthread_mutex_unlock: ERR=%s\n", strerror(stat)); jq->num_workers--; return NULL; } /* Call user's routine here */ - Dmsg1(100, "Calling user engine for jobid=%d\n", jcr->JobId); + Dmsg1(010, "Calling user engine for jobid=%d\n", jcr->JobId); jq->engine(je->jcr); - Dmsg1(100, "Back from user engine jobid=%d.\n", jcr->JobId); + Dmsg1(010, "Back from user engine jobid=%d.\n", jcr->JobId); if ((stat = pthread_mutex_lock(&jq->mutex)) != 0) { + Jmsg1(NULL, M_ERROR, 0, "pthread_mutex_unlock: ERR=%s\n", strerror(stat)); jq->num_workers--; free(je); /* release job entry */ return NULL; } - Dmsg0(200, "Done lock mutex\n"); + Dmsg0(200, "Done lock mutex after running job. Release locks.\n"); jq->running_jobs->remove(je); /* * Release locks if acquired. Note, they will not have @@ -440,12 +456,12 @@ static void *jobq_server(void *arg) */ jcr->reschedule_count++; jcr->sched_time = time(NULL) + jcr->job->RescheduleInterval; - Dmsg2(100, "Rescheduled Job %s to re-run in %d seconds.\n", jcr->Job, + Dmsg2(010, "Rescheduled Job %s to re-run in %d seconds.\n", jcr->Job, (int)jcr->job->RescheduleInterval); jcr->JobStatus = JS_Created; /* force new status */ dird_free_jcr(jcr); /* partial cleanup old stuff */ if (jcr->JobBytes == 0) { - Dmsg1(100, "Requeue job=%d\n", jcr->JobId); + Dmsg1(010, "Requeue job=%d\n", jcr->JobId); V(jq->mutex); jobq_add(jq, jcr); /* queue the job to run again */ P(jq->mutex); @@ -466,20 +482,19 @@ static void *jobq_server(void *arg) njcr->pool = jcr->pool; njcr->store = jcr->store; njcr->messages = jcr->messages; - Dmsg0(100, "Call to run new job\n"); + Dmsg0(010, "Call to run new job\n"); V(jq->mutex); run_job(njcr); /* This creates a "new" job */ free_jcr(njcr); /* release "new" jcr */ P(jq->mutex); - Dmsg0(100, "Back from running new job.\n"); + Dmsg0(010, "Back from running new job.\n"); } /* Clean up and release old jcr */ if (jcr->db) { - Dmsg0(100, "Close DB\n"); db_close_database(jcr, jcr->db); jcr->db = NULL; } - Dmsg1(100, "====== Termination job=%d\n", jcr->JobId); + Dmsg1(010, "====== Termination job=%d\n", jcr->JobId); free_jcr(jcr); free(je); /* release job entry */ } @@ -487,17 +502,17 @@ static void *jobq_server(void *arg) * If any job in the wait queue can be run, * move it to the ready queue */ - Dmsg0(100, "Done check ready, now check wait queue.\n"); + Dmsg0(010, "Done check ready, now check wait queue.\n"); while (!jq->waiting_jobs->empty() && !jq->quit) { int Priority; je = (jobq_item_t *)jq->waiting_jobs->first(); jobq_item_t *re = (jobq_item_t *)jq->running_jobs->first(); if (re) { Priority = re->jcr->JobPriority; - Dmsg1(100, "Set Run pri=%d\n", Priority); + Dmsg2(010, "JobId %d is running. Set pri=%d\n", re->jcr->JobId, Priority); } else { Priority = je->jcr->JobPriority; - Dmsg1(100, "Set Job pri=%d\n", Priority); + Dmsg1(010, "No job running. Set Job pri=%d\n", Priority); } /* * Walk down the list of waiting jobs and attempt @@ -507,7 +522,7 @@ static void *jobq_server(void *arg) /* je is current job item on the queue, jn is the next one */ JCR *jcr = je->jcr; jobq_item_t *jn = (jobq_item_t *)jq->waiting_jobs->next(je); - Dmsg3(100, "Examining Job=%d JobPri=%d want Pri=%d\n", + Dmsg3(010, "Examining Job=%d JobPri=%d want Pri=%d\n", jcr->JobId, jcr->JobPriority, Priority); /* Take only jobs of correct Priority */ if (jcr->JobPriority != Priority) { @@ -544,41 +559,41 @@ static void *jobq_server(void *arg) jcr->acquired_resource_locks = true; jq->waiting_jobs->remove(je); jq->ready_jobs->append(je); - Dmsg1(100, "moved JobId=%d from wait to ready queue\n", je->jcr->JobId); + Dmsg1(010, "moved JobId=%d from wait to ready queue\n", je->jcr->JobId); je = jn; } /* end for loop */ break; } /* end while loop */ - Dmsg0(100, "Done checking wait queue.\n"); + Dmsg0(010, "Done checking wait queue.\n"); /* * If no more ready work and we are asked to quit, then do it */ if (jq->ready_jobs->empty() && jq->quit) { jq->num_workers--; if (jq->num_workers == 0) { - Dmsg0(100, "Wake up destroy routine\n"); + Dmsg0(010, "Wake up destroy routine\n"); /* Wake up destroy routine if he is waiting */ pthread_cond_broadcast(&jq->work); } break; } - Dmsg0(100, "Check for work request\n"); + Dmsg0(010, "Check for work request\n"); /* * If no more work requests, and we waited long enough, quit */ - Dmsg2(100, "timedout=%d read empty=%d\n", timedout, + Dmsg2(010, "timedout=%d read empty=%d\n", timedout, jq->ready_jobs->empty()); if (jq->ready_jobs->empty() && timedout) { - Dmsg0(100, "break big loop\n"); + Dmsg0(010, "break big loop\n"); jq->num_workers--; break; } - Dmsg0(100, "Loop again\n"); - work = false; + work = !jq->ready_jobs->empty() || !jq->waiting_jobs->empty(); + Dmsg1(010, "Loop again. work=%d\n", work); } /* end of big for loop */ Dmsg0(200, "unlock mutex\n"); pthread_mutex_unlock(&jq->mutex); - Dmsg0(100, "End jobq_server\n"); + Dmsg0(010, "End jobq_server\n"); return NULL; } diff --git a/bacula/src/dird/scheduler.c b/bacula/src/dird/scheduler.c index 3c7f52721d..2d5cd58158 100644 --- a/bacula/src/dird/scheduler.c +++ b/bacula/src/dird/scheduler.c @@ -32,6 +32,8 @@ #include "bacula.h" #include "dird.h" +#define PHIL + /* Local variables */ struct job_item { @@ -99,7 +101,6 @@ JCR *wait_for_next_job(char *one_shot_job_to_run) bmicrosleep(NEXT_CHECK_SECS, 0); /* recheck once per minute */ } -#define list_chain #ifdef list_chain job_item *je; foreach_dlist(je, jobs_to_run) { @@ -311,13 +312,13 @@ static void add_job(JOB *job, RUN *run, time_t now, time_t runtime) * do run any job scheduled less than a minute ago. */ if (((runtime - run->last_run) < 61) || ((runtime+59) < now)) { -#ifdef xxx - char dt[50], dt1[50]; - bstrftime(dt, sizeof(dt), runtime); - strcpy(dt+7, dt+9); /* cut century */ - bstrftime(dt1, sizeof(dt1), now); - strcpy(dt1+7, dt1+9); /* cut century */ - Dmsg2(000, "runtime=%s now=%s\n", dt, dt1); +#ifdef PHIL + char dt[50], dt1[50], dt2[50]; + bstrftime_nc(dt, sizeof(dt), runtime); + bstrftime_nc(dt1, sizeof(dt1), run->last_run); + bstrftime_nc(dt2, sizeof(dt2), now); + Dmsg4(000, "Drop: Job=%s run=%s. last_run=%s. now=%s\n", job->hdr.name, + dt, dt1, dt2); #endif return; } @@ -351,12 +352,16 @@ static void add_job(JOB *job, RUN *run, time_t now, time_t runtime) static void dump_job(job_item *ji, char *msg) { +#ifdef PHIL char dt[MAX_TIME_LENGTH]; + int save_debug = debug_level; + debug_level = 200; if (debug_level < 200) { return; } - bstrftime(dt, sizeof(dt), ji->runtime); - strcpy(dt+7, dt+9); /* cut century */ + bstrftime_nc(dt, sizeof(dt), ji->runtime); Dmsg4(200, "%s: Job=%s priority=%d run %s\n", msg, ji->job->hdr.name, ji->Priority, dt); + debug_level = save_debug; +#endif } diff --git a/bacula/src/dird/ua_cmds.c b/bacula/src/dird/ua_cmds.c index 2f4473eb45..e9fb8868e7 100644 --- a/bacula/src/dird/ua_cmds.c +++ b/bacula/src/dird/ua_cmds.c @@ -39,6 +39,7 @@ extern struct s_res resources[]; extern char my_name[]; extern jobq_t job_queue; /* job queue */ + extern char *list_pool; /* Imported functions */ @@ -65,6 +66,7 @@ static int add_cmd(UAContext *ua, char *cmd); static int create_cmd(UAContext *ua, char *cmd); static int cancel_cmd(UAContext *ua, char *cmd); static int setdebug_cmd(UAContext *ua, char *cmd); +static int trace_cmd(UAContext *ua, char *cmd); static int var_cmd(UAContext *ua, char *cmd); static int estimate_cmd(UAContext *ua, char *cmd); static int help_cmd(UAContext *ua, char *cmd); @@ -119,6 +121,7 @@ static struct cmdstruct commands[] = { { N_("show"), show_cmd, _("show (resource records) [jobs | pools | ... | all]")}, { N_("sqlquery"), sqlquerycmd, _("use SQL to query catalog")}, { N_("time"), time_cmd, _("print current time")}, + { N_("trace"), trace_cmd, _("turn on/off trace to file")}, { N_("unmount"), unmount_cmd, _("unmount ")}, { N_("update"), update_cmd, _("update Volume or Pool")}, { N_("use"), use_cmd, _("use catalog xxx")}, @@ -1091,7 +1094,7 @@ static int update_pool(UAContext *ua) } -static void do_storage_setdebug(UAContext *ua, STORE *store, int level) +static void do_storage_setdebug(UAContext *ua, STORE *store, int level, int trace_flag) { BSOCK *sd; @@ -1105,7 +1108,7 @@ static void do_storage_setdebug(UAContext *ua, STORE *store, int level) } Dmsg0(120, _("Connected to storage daemon\n")); sd = ua->jcr->store_bsock; - bnet_fsend(sd, "setdebug=%d\n", level); + bnet_fsend(sd, "setdebug=%d trace=%d\n", level, trace_flag); if (bnet_recv(sd) >= 0) { bsendmsg(ua, "%s", sd->msg); } @@ -1115,7 +1118,7 @@ static void do_storage_setdebug(UAContext *ua, STORE *store, int level) return; } -static void do_client_setdebug(UAContext *ua, CLIENT *client, int level) +static void do_client_setdebug(UAContext *ua, CLIENT *client, int level, int trace_flag) { BSOCK *fd; @@ -1131,7 +1134,7 @@ static void do_client_setdebug(UAContext *ua, CLIENT *client, int level) } Dmsg0(120, "Connected to file daemon\n"); fd = ua->jcr->file_bsock; - bnet_fsend(fd, "setdebug=%d\n", level); + bnet_fsend(fd, "setdebug=%d trace=%d\n", level, trace_flag); if (bnet_recv(fd) >= 0) { bsendmsg(ua, "%s", fd->msg); } @@ -1142,7 +1145,7 @@ static void do_client_setdebug(UAContext *ua, CLIENT *client, int level) } -static void do_all_setdebug(UAContext *ua, int level) +static void do_all_setdebug(UAContext *ua, int level, int trace_flag) { STORE *store, **unique_store; CLIENT *client, **unique_client; @@ -1179,7 +1182,7 @@ static void do_all_setdebug(UAContext *ua, int level) /* Call each unique Storage daemon */ for (j=0; jpint32_val; } + /* Look for trace flag. -1 => not change */ + i = find_arg_with_value(ua, _("trace")); + if (i >= 0) { + trace_flag = atoi(ua->argv[i]); + if (trace_flag > 0) { + trace_flag = 1; + } + } + /* General debug? */ for (i=1; iargc; i++) { if (strcasecmp(ua->argk[i], _("all")) == 0) { - do_all_setdebug(ua, level); + do_all_setdebug(ua, level, trace_flag); return 1; } if (strcasecmp(ua->argk[i], _("dir")) == 0 || strcasecmp(ua->argk[i], _("director")) == 0) { debug_level = level; + set_trace(trace_flag); return 1; } if (strcasecmp(ua->argk[i], _("client")) == 0 || @@ -1260,13 +1274,13 @@ static int setdebug_cmd(UAContext *ua, char *cmd) if (ua->argv[i]) { client = (CLIENT *)GetResWithName(R_CLIENT, ua->argv[i]); if (client) { - do_client_setdebug(ua, client, level); + do_client_setdebug(ua, client, level, trace_flag); return 1; } } client = select_client_resource(ua); if (client) { - do_client_setdebug(ua, client, level); + do_client_setdebug(ua, client, level, trace_flag); return 1; } } @@ -1278,13 +1292,13 @@ static int setdebug_cmd(UAContext *ua, char *cmd) if (ua->argv[i]) { store = (STORE *)GetResWithName(R_STORAGE, ua->argv[i]); if (store) { - do_storage_setdebug(ua, store, level); + do_storage_setdebug(ua, store, level, trace_flag); return 1; } } store = get_storage_resource(ua, 0); if (store) { - do_storage_setdebug(ua, store, level); + do_storage_setdebug(ua, store, level, trace_flag); return 1; } } @@ -1301,21 +1315,22 @@ static int setdebug_cmd(UAContext *ua, char *cmd) switch(do_prompt(ua, "", _("Select daemon type to set debug level"), NULL, 0)) { case 0: /* Director */ debug_level = level; + set_trace(trace_flag); break; case 1: store = get_storage_resource(ua, 0); if (store) { - do_storage_setdebug(ua, store, level); + do_storage_setdebug(ua, store, level, trace_flag); } break; case 2: client = select_client_resource(ua); if (client) { - do_client_setdebug(ua, client, level); + do_client_setdebug(ua, client, level, trace_flag); } break; case 3: - do_all_setdebug(ua, level); + do_all_setdebug(ua, level, trace_flag); break; default: break; @@ -1323,6 +1338,27 @@ static int setdebug_cmd(UAContext *ua, char *cmd) return 1; } +/* + * Turn debug tracing to file on/off + */ +static int trace_cmd(UAContext *ua, char *cmd) +{ + char *onoff; + + if (ua->argc != 2) { + if (!get_cmd(ua, _("Turn on or off? "))) { + return 1; + } + onoff = ua->cmd; + } else { + onoff = ua->argk[1]; + } + + set_trace((strcasecmp(onoff, _("off")) == 0) ? false : true); + return 1; + +} + static int var_cmd(UAContext *ua, char *cmd) { POOLMEM *val = get_pool_memory(PM_FNAME); diff --git a/bacula/src/dird/ua_output.c b/bacula/src/dird/ua_output.c index 27ac035772..d3a5286c7d 100644 --- a/bacula/src/dird/ua_output.c +++ b/bacula/src/dird/ua_output.c @@ -523,7 +523,7 @@ RUN *find_next_run(RUN *run, JOB *job, time_t &runtime) tm.tm_sec = 0; runtime = mktime(&tm); if (runtime > now) { - Dmsg2(000, "Found it level=%d %c\n", run->level, run->level); + Dmsg2(100, "Found it level=%d %c\n", run->level, run->level); return run; /* found it, return run resource */ } } diff --git a/bacula/src/filed/job.c b/bacula/src/filed/job.c index cdd886d65b..33238d6cd9 100644 --- a/bacula/src/filed/job.c +++ b/bacula/src/filed/job.c @@ -281,15 +281,16 @@ static int cancel_cmd(JCR *jcr) static int setdebug_cmd(JCR *jcr) { BSOCK *dir = jcr->dir_bsock; - int level; + int level, trace_flag; Dmsg1(110, "setdebug_cmd: %s", dir->msg); - if (sscanf(dir->msg, "setdebug=%d", &level) != 1 || level < 0) { + if (sscanf(dir->msg, "setdebug=%d", &level, &trace_flag) != 2 || level < 0) { pm_strcpy(&jcr->errmsg, dir->msg); bnet_fsend(dir, "2991 Bad setdebug command: %s\n", jcr->errmsg); return 0; } debug_level = level; + set_trace(trace_flag); return bnet_fsend(dir, OKsetdebug, level); } diff --git a/bacula/src/lib/message.c b/bacula/src/lib/message.c index 168edf630c..08ba4dd835 100755 --- a/bacula/src/lib/message.c +++ b/bacula/src/lib/message.c @@ -49,7 +49,6 @@ int console_msg_pending = 0; char con_fname[500]; /* Console filename */ FILE *con_fd = NULL; /* Console file descriptor */ brwlock_t con_lock; /* Console lock structure */ -FILE *trace_fd = NULL; #ifdef HAVE_POSTGRESQL char catalog_db[] = "PostgreSQL"; @@ -68,6 +67,12 @@ char catalog_db[] = "Internal"; const char *host_os = HOST_OS; const char *distname = DISTNAME; const char *distver = DISTVER; +static FILE *trace_fd = NULL; +#ifdef HAVE_WIN32 +static bool trace = true; +#else +static bool trace = false; +#endif /* Forward referenced functions */ @@ -746,15 +751,6 @@ d_msg(const char *file, int line, int level, const char *fmt,...) } if (level <= debug_level) { -#ifdef HAVE_WIN32 -#define SEND_DMSG_TO_FILE -#endif -#ifdef SEND_DMSG_TO_FILE - if (!trace_fd) { - bsnprintf(buf, sizeof(buf), "%s/bacula.trace", working_directory ? working_directory : "."); - trace_fd = fopen(buf, "a+"); - } -#endif #ifdef FULL_LOCATION if (details) { /* visual studio passes the whole path to the file as well @@ -773,17 +769,44 @@ d_msg(const char *file, int line, int level, const char *fmt,...) bvsnprintf(buf+len, sizeof(buf)-len, (char *)fmt, arg_ptr); va_end(arg_ptr); -#ifdef SEND_DMSG_TO_FILE - if (trace_fd) { - fputs(buf, trace_fd); - fflush(trace_fd); + /* + * Used the "trace on" command in the console to turn on + * output to the trace file. "trace off" will close the file. + */ + if (trace) { + if (!trace_fd) { + bsnprintf(buf, sizeof(buf), "%s/bacula.trace", working_directory ? working_directory : "."); + trace_fd = fopen(buf, "a+"); + } + if (trace_fd) { + fputs(buf, trace_fd); + fflush(trace_fd); + } + } else { /* not tracing */ + fputs(buf, stdout); } -#else - fputs(buf, stdout); -#endif } } +/* + * Set trace flag on/off. If argument is negative, there is no change + */ +void set_trace(int trace_flag) +{ + if (trace_flag < 0) { + return; + } else if (trace_flag > 0) { + trace = true; + } else { + trace = false; + } + if (!trace && trace_fd) { + FILE *ltrace_fd = trace_fd; + trace_fd = NULL; + bmicrosleep(0, 100000); /* yield to prevent seg faults */ + fclose(ltrace_fd); + } +} /********************************************************************* * diff --git a/bacula/src/lib/protos.h b/bacula/src/lib/protos.h index 5f97e090d8..6269700a6f 100644 --- a/bacula/src/lib/protos.h +++ b/bacula/src/lib/protos.h @@ -153,6 +153,7 @@ void free_msgs_res (MSGS *msgs); int open_spool_file (JCR *jcr, BSOCK *bs); int close_spool_file (JCR *jcr, BSOCK *bs); void dequeue_messages (JCR *jcr); +void set_trace (int trace_flag); /* bnet_server.c */ diff --git a/bacula/src/version.h b/bacula/src/version.h index 2872038323..f50e7891df 100644 --- a/bacula/src/version.h +++ b/bacula/src/version.h @@ -2,8 +2,8 @@ #undef VERSION #define VERSION "1.33.4" #define VSTRING "1" -#define BDATE "01 Mar 2004" -#define LSMDATE "01Mar04" +#define BDATE "02 Mar 2004" +#define LSMDATE "02Mar04" /* Debug flags */ #undef DEBUG