tools/xenstore: introduce trace classes

Make the xenstored internal trace configurable by adding classes
which can be switched on and off independently from each other.

Define the following classes:

- obj: Creation and deletion of interesting "objects" (watch,
  transaction, connection)
- io: incoming requests and outgoing responses
- wrl: write limiting

Per default "obj" and "io" are switched on.

Entries written via trace() will always be printed (if tracing is on
at all).

Add the capability to control the trace settings via the "log"
command and via a new "--log-control" command line option.

Add a missing trace_create() call for creating a transaction.

Signed-off-by: Juergen Gross <jgross@suse.com>
Reviewed-by: Julien Grall <jgrall@amazon.com>

diff --git a/docs/misc/xenstore.txt b/docs/misc/xenstore.txt
index 44428ae3a755dd4b000c43206c9294112f8f750c..8887e7df88140a7357f006bb8a37a5da9b2eaae6 100644 (file)
--- a/docs/misc/xenstore.txt
+++ b/docs/misc/xenstore.txt
@@ -409,10 +409,12 @@ CONTROL                   <command>|[<parameters>|]
                error string in case of failure. -s can return "BUSY" in case
                of an active transaction, a retry of -s can be done in that
                case.
-       log|on
-               turn xenstore logging on
-       log|off
-               turn xenstore logging off
+       log|[on|off|+<switch>|-<switch>]
+               without parameters: show possible log switches
+               on: turn xenstore logging on
+               off: turn xenstore logging off
+               +<switch>: activates log entries for <switch>,
+               -<switch>: deactivates log entries for <switch>
        logfile|<file-name>
                log to specified file
        memreport|[<file-name>]

diff --git a/tools/xenstore/xenstored_control.c b/tools/xenstore/xenstored_control.c
index 41e6992591c7f321950d9333354b5ada3e4739e1..000b2bb8c7abe491b2dba7999ef7a328fffeb9fa 100644 (file)
--- a/tools/xenstore/xenstored_control.c
+++ b/tools/xenstore/xenstored_control.c
@@ -182,6 +182,28 @@ static int do_control_check(const void *ctx, struct connection *conn,
 static int do_control_log(const void *ctx, struct connection *conn,
                          char **vec, int num)
 {
+       int ret;
+
+       if (num == 0) {
+               char *resp = talloc_asprintf(ctx, "Log switch settings:\n");
+               unsigned int idx;
+               bool on;
+
+               if (!resp)
+                       return ENOMEM;
+               for (idx = 0; trace_switches[idx]; idx++) {
+                       on = trace_flags & (1u << idx);
+                       resp = talloc_asprintf_append(resp, "%-8s: %s\n",
+                                                     trace_switches[idx],
+                                                     on ? "on" : "off");
+                       if (!resp)
+                               return ENOMEM;
+               }
+
+               send_reply(conn, XS_CONTROL, resp, strlen(resp) + 1);
+               return 0;
+       }
+
        if (num != 1)
                return EINVAL;
 
@@ -189,8 +211,11 @@ static int do_control_log(const void *ctx, struct connection *conn,
                reopen_log();
        else if (!strcmp(vec[0], "off"))
                close_log();
-       else
-               return EINVAL;
+       else {
+               ret = set_trace_switch(vec[0]);
+               if (ret)
+                       return ret;
+       }
 
        send_ack(conn, XS_CONTROL);
        return 0;
@@ -923,7 +948,7 @@ static int do_control_help(const void *, struct connection *, char **, int);
 
 static struct cmd_s cmds[] = {
        { "check", do_control_check, "" },
-       { "log", do_control_log, "on|off" },
+       { "log", do_control_log, "[on|off|+<switch>|-<switch>]" },
 
 #ifndef NO_LIVE_UPDATE
        /*

diff --git a/tools/xenstore/xenstored_core.c b/tools/xenstore/xenstored_core.c
index 17e678256e01c4c99cfb98db033f917767830489..c2c2c342deb4d3491ce1ef226fa4a8d8a3314bec 100644 (file)
--- a/tools/xenstore/xenstored_core.c
+++ b/tools/xenstore/xenstored_core.c
@@ -85,6 +85,7 @@ static int reopen_log_pipe[2];
 static int reopen_log_pipe0_pollfd_idx = -1;
 char *tracefile = NULL;
 TDB_CONTEXT *tdb_ctx = NULL;
+unsigned int trace_flags = TRACE_OBJ | TRACE_IO;
 
 static const char *sockmsg_string(enum xsd_sockmsg_type type);
 
@@ -139,13 +140,13 @@ static void trace_io(const struct connection *conn,
        time_t now;
        struct tm *tm;
 
-       if (tracefd < 0)
+       if (tracefd < 0 || !(trace_flags & TRACE_IO))
                return;
 
        now = time(NULL);
        tm = localtime(&now);
 
-       trace("%s %p %04d%02d%02d %02d:%02d:%02d %s (",
+       trace("io: %s %p %04d%02d%02d %02d:%02d:%02d %s (",
              out ? "OUT" : "IN", conn,
              tm->tm_year + 1900, tm->tm_mon + 1,
              tm->tm_mday, tm->tm_hour, tm->tm_min, tm->tm_sec,
@@ -158,12 +159,14 @@ static void trace_io(const struct connection *conn,
 
 void trace_create(const void *data, const char *type)
 {
-       trace("CREATE %s %p\n", type, data);
+       if (trace_flags & TRACE_OBJ)
+               trace("obj: CREATE %s %p\n", type, data);
 }
 
 void trace_destroy(const void *data, const char *type)
 {
-       trace("DESTROY %s %p\n", type, data);
+       if (trace_flags & TRACE_OBJ)
+               trace("obj: DESTROY %s %p\n", type, data);
 }
 
 /**
@@ -2599,6 +2602,8 @@ static void usage(void)
 "  -N, --no-fork           to request that the daemon does not fork,\n"
 "  -P, --output-pid        to request that the pid of the daemon is output,\n"
 "  -T, --trace-file <file> giving the file for logging, and\n"
+"      --trace-control=+<switch> activate a specific <switch>\n"
+"      --trace-control=-<switch> deactivate a specific <switch>\n"
 "  -E, --entry-nb <nb>     limit the number of entries per domain,\n"
 "  -S, --entry-size <size> limit the size of entry per domain, and\n"
 "  -W, --watch-nb <nb>     limit the number of watches per domain,\n"
@@ -2642,6 +2647,7 @@ static struct option options[] = {
        { "output-pid", 0, NULL, 'P' },
        { "entry-size", 1, NULL, 'S' },
        { "trace-file", 1, NULL, 'T' },
+       { "trace-control", 1, NULL, 1 },
        { "transaction", 1, NULL, 't' },
        { "perm-nb", 1, NULL, 'A' },
        { "path-max", 1, NULL, 'M' },
@@ -2716,6 +2722,43 @@ static void set_quota(const char *arg, bool soft)
                barf("unknown quota \"%s\"\n", arg);
 }
 
+/* Sorted by bit values of TRACE_* flags. Flag is (1u << index). */
+const char *const trace_switches[] = {
+       "obj", "io", "wrl",
+       NULL
+};
+
+int set_trace_switch(const char *arg)
+{
+       bool remove = (arg[0] == '-');
+       unsigned int idx;
+
+       switch (arg[0]) {
+       case '-':
+               remove = true;
+               break;
+       case '+':
+               remove = false;
+               break;
+       default:
+               return EINVAL;
+       }
+
+       arg++;
+
+       for (idx = 0; trace_switches[idx]; idx++) {
+               if (!strcmp(arg, trace_switches[idx])) {
+                       if (remove)
+                               trace_flags &= ~(1u << idx);
+                       else
+                               trace_flags |= 1u << idx;
+                       return 0;
+               }
+       }
+
+       return EINVAL;
+}
+
 int main(int argc, char *argv[])
 {
        int opt;
@@ -2764,6 +2807,10 @@ int main(int argc, char *argv[])
                case 'T':
                        tracefile = optarg;
                        break;
+               case 1:
+                       if (set_trace_switch(optarg))
+                               barf("Illegal trace switch \"%s\"\n", optarg);
+                       break;
                case 'I':
                        if (optarg && !strcmp(optarg, "off"))
                                tdb_flags = 0;

diff --git a/tools/xenstore/xenstored_core.h b/tools/xenstore/xenstored_core.h
index 6548200d8e8ac7f1fb33ae0f4b7a3cd49ca902b3..c59b06551f543b3909fdb6a49ef57ff9db000d45 100644 (file)
--- a/tools/xenstore/xenstored_core.h
+++ b/tools/xenstore/xenstored_core.h
@@ -294,6 +294,14 @@ extern char **orig_argv;
 extern char *tracefile;
 extern int tracefd;
 
+/* Trace flag values must be kept in sync with trace_switches[] contents. */
+extern unsigned int trace_flags;
+#define TRACE_OBJ      0x00000001
+#define TRACE_IO       0x00000002
+#define TRACE_WRL      0x00000004
+extern const char *const trace_switches[];
+int set_trace_switch(const char *arg);
+
 extern TDB_CONTEXT *tdb_ctx;
 extern int dom0_domid;
 extern int dom0_event;

diff --git a/tools/xenstore/xenstored_domain.c b/tools/xenstore/xenstored_domain.c
index 4f4c0a727cbbae4a23e87f8c76b33a9bc653b23e..e9d84d7c24f6149c882dcb729fc749c1f74ee4b8 100644 (file)
--- a/tools/xenstore/xenstored_domain.c
+++ b/tools/xenstore/xenstored_domain.c
@@ -1261,6 +1261,12 @@ static long wrl_ndomains;
 static wrl_creditt wrl_reserve; /* [-wrl_config_newdoms_dburst, +_gburst ] */
 static time_t wrl_log_last_warning; /* 0: no previous warning */
 
+#define trace_wrl(...)                         \
+do {                                           \
+       if (trace_flags & TRACE_WRL)            \
+               trace("wrl: " __VA_ARGS__);     \
+} while (0)
+
 void wrl_gettime_now(struct wrl_timestampt *now_wt)
 {
        struct timespec now_ts;
@@ -1366,12 +1372,9 @@ void wrl_credit_update(struct domain *domain, struct wrl_timestampt now)
 
        domain->wrl_timestamp = now;
 
-       trace("wrl: dom %4d %6ld  msec  %9ld credit   %9ld reserve"
-             "  %9ld discard\n",
-             domain->domid,
-             msec,
-             (long)domain->wrl_credit, (long)wrl_reserve,
-             (long)surplus);
+       trace_wrl("dom %4d %6ld msec %9ld credit %9ld reserve %9ld discard\n",
+                 domain->domid, msec, (long)domain->wrl_credit,
+                 (long)wrl_reserve, (long)surplus);
 }
 
 void wrl_check_timeout(struct domain *domain,
@@ -1403,10 +1406,9 @@ void wrl_check_timeout(struct domain *domain,
        if (*ptimeout==-1 || wakeup < *ptimeout)
                *ptimeout = wakeup;
 
-       trace("wrl: domain %u credit=%ld (reserve=%ld) SLEEPING for %d\n",
-             domain->domid,
-             (long)domain->wrl_credit, (long)wrl_reserve,
-             wakeup);
+       trace_wrl("domain %u credit=%ld (reserve=%ld) SLEEPING for %d\n",
+                 domain->domid, (long)domain->wrl_credit, (long)wrl_reserve,
+                 wakeup);
 }
 
 #define WRL_LOG(now, ...) \
@@ -1424,9 +1426,8 @@ void wrl_apply_debit_actual(struct domain *domain)
        wrl_credit_update(domain, now);
 
        domain->wrl_credit -= wrl_config_writecost;
-       trace("wrl: domain %u credit=%ld (reserve=%ld)\n",
-             domain->domid,
-             (long)domain->wrl_credit, (long)wrl_reserve);
+       trace_wrl("domain %u credit=%ld (reserve=%ld)\n", domain->domid,
+                 (long)domain->wrl_credit, (long)wrl_reserve);
 
        if (domain->wrl_credit < 0) {
                if (!domain->wrl_delay_logged) {

diff --git a/tools/xenstore/xenstored_transaction.c b/tools/xenstore/xenstored_transaction.c
index 82e5e66c188248a6ee03edf499b0361679a3744b..1aa9d3cb3dce2792256e0f373f1f6e65f8523e35 100644 (file)
--- a/tools/xenstore/xenstored_transaction.c
+++ b/tools/xenstore/xenstored_transaction.c
@@ -475,6 +475,7 @@ int do_transaction_start(const void *ctx, struct connection *conn,
        if (!trans)
                return ENOMEM;
 
+       trace_create(trans, "transaction");
        INIT_LIST_HEAD(&trans->accessed);
        INIT_LIST_HEAD(&trans->changed_domains);
        trans->conn = conn;