dle-develop — Dependable Linux Effort mailing list for developers

Re: [Dle-develop] [PATCH v5] Add timestamp to error_report()

[Stefan H. <ste...@gm...>]

On Tue, Jul 02, 2013 at 02:09:24PM +0000, Seiji Aguchi wrote:
> > > diff --git a/util/qemu-time.c b/util/qemu-time.c
> > > new file mode 100644
> > > index 0000000..3862788
> > > --- /dev/null
> > > +++ b/util/qemu-time.c
> > > @@ -0,0 +1,26 @@
> > > +/*
> > > + * Time handling
> > > + *
> > > + * Copyright (C) 2013 Hitachi Data Systems Corp.
> > > + *
> > > + * Authors:
> > > + *  Seiji Aguchi <sei...@hd...>
> > > + *
> > > + * This work is licensed under the terms of the GNU GPL, version 2 or later.
> > > + * See the COPYING file in the top-level directory.
> > > + */
> > > +#include "qemu/time.h"
> > > +
> > > +void qemu_get_timestamp_str(char *timestr, size_t len)
> > > +{
> > > +    GTimeVal tv;
> > > +    gchar *tmp_str = NULL;
> > > +
> > > +    /* Size of len should be at least TIMESTAMP_LEN to avoid truncation */
> > > +    assert(len >= TIMESTAMP_LEN);
> > > +
> > > +    g_get_current_time(&tv);
> > > +    tmp_str = g_time_val_to_iso8601(&tv);
> > > +    g_strlcpy((gchar *)timestr, tmp_str, len);
> > > +    g_free(tmp_str);
> > > +}
> > 
> > Why strcpy into a fixed-size buffer when glib gives us a heap-allocated
> > string?
> > 
> > This patch would be simpler by dropping qemu-time.c/time.h 
> 
> I plan to introduce timestamp to monitor_printf() and fprintf()
> near future.
> 
> In this case, it is better from a maintenance POV to keep time-handling
>  functionality  in a file that's separate from the qemu error file, so it can be reused
> elsewhere in QEMU if needed.
> 
> It is suggested by Daniel.
> http://marc.info/?l=qemu-devel&m=136741113218944&w=2

Daniel's statement was about the code you copied from libvirt.  It was
not about using the glib function, which simplifies things greatly and
avoids the need for a test suite.

Patches need to make sense today, please do not add extra code with
potential future use in mind:

1. Other developers must be able to read and modify the current codebase
   on its own.  They do not know what potential future changes you were
   thinking about.

2. You may never end up submitting or getting the future stuff upstream.
   Then we'd be left with extra layers that are never used.

Stefan

Re: [Dle-develop] [PATCH v5] Add timestamp to error_report()

[Seiji A. <sei...@hd...>]

> > +DEF("msg", HAS_ARG, QEMU_OPTION_msg,
> > +    "-msg [timestamp=on|off]\n"
> > +    "  change the format of messages\n"
> > +    "  timestamp=on|off enables leading timestamps (default:on)\n",
> > +    QEMU_ARCH_ALL)
> > +STEXI
> > +@item -msg timestamp=on|off
> > +@findex -msg
> > +prepend a timestamp to each log message.
> > +(disabled by default)
> > +ETEXI
> 
> I am confused.  If the user specifies -msg then enable_timestamp_msg is
> on by default.  If the user does not specify -msg then
> enable_timestmap_msg is off.  Did I get that right?

Yes.

> 
> This means that the default behavior of QEMU does not change but you can
> add -msg to enable timestamps.
> 
> I'm happy with this but find the documentation confusing.

I can remove "(disabled by default)" if needed.

> 
> > diff --git a/util/qemu-time.c b/util/qemu-time.c
> > new file mode 100644
> > index 0000000..3862788
> > --- /dev/null
> > +++ b/util/qemu-time.c
> > @@ -0,0 +1,26 @@
> > +/*
> > + * Time handling
> > + *
> > + * Copyright (C) 2013 Hitachi Data Systems Corp.
> > + *
> > + * Authors:
> > + *  Seiji Aguchi <sei...@hd...>
> > + *
> > + * This work is licensed under the terms of the GNU GPL, version 2 or later.
> > + * See the COPYING file in the top-level directory.
> > + */
> > +#include "qemu/time.h"
> > +
> > +void qemu_get_timestamp_str(char *timestr, size_t len)
> > +{
> > +    GTimeVal tv;
> > +    gchar *tmp_str = NULL;
> > +
> > +    /* Size of len should be at least TIMESTAMP_LEN to avoid truncation */
> > +    assert(len >= TIMESTAMP_LEN);
> > +
> > +    g_get_current_time(&tv);
> > +    tmp_str = g_time_val_to_iso8601(&tv);
> > +    g_strlcpy((gchar *)timestr, tmp_str, len);
> > +    g_free(tmp_str);
> > +}
> 
> Why strcpy into a fixed-size buffer when glib gives us a heap-allocated
> string?
> 
> This patch would be simpler by dropping qemu-time.c/time.h 

I plan to introduce timestamp to monitor_printf() and fprintf()
near future.

In this case, it is better from a maintenance POV to keep time-handling
 functionality  in a file that's separate from the qemu error file, so it can be reused
elsewhere in QEMU if needed.

It is suggested by Daniel.
http://marc.info/?l=qemu-devel&m=136741113218944&w=2

> and simply
> doing:
> 
> if (enable_timestamp_msg) {
>     GTimeVal tv;
>     gchar *timestamp;
> 
>     g_get_current_time(&tv);
>     timestamp = g_time_val_to_iso8601(&tv);
>     error_printf("%s ", timestamp);
>     g_free(timestamp);

I'm concerned that we may have potential memory leak
If someone neglect to call the g_free().
That is why I use the fixed-size buffer.

Seiji

Re: [Dle-develop] [PATCH v5] Add timestamp to error_report()

[Stefan H. <ste...@gm...>]

On Mon, Jul 01, 2013 at 02:54:07PM -0400, Seiji Aguchi wrote:
> diff --git a/qemu-options.hx b/qemu-options.hx
> index ca6fdf6..a6dac1a 100644
> --- a/qemu-options.hx
> +++ b/qemu-options.hx
> @@ -3102,3 +3102,15 @@ HXCOMM This is the last statement. Insert new options before this line!
>  STEXI
>  @end table
>  ETEXI
> +
> +DEF("msg", HAS_ARG, QEMU_OPTION_msg,
> +    "-msg [timestamp=on|off]\n"
> +    "  change the format of messages\n"
> +    "  timestamp=on|off enables leading timestamps (default:on)\n",
> +    QEMU_ARCH_ALL)
> +STEXI
> +@item -msg timestamp=on|off
> +@findex -msg
> +prepend a timestamp to each log message.
> +(disabled by default)
> +ETEXI

I am confused.  If the user specifies -msg then enable_timestamp_msg is
on by default.  If the user does not specify -msg then
enable_timestmap_msg is off.  Did I get that right?

This means that the default behavior of QEMU does not change but you can
add -msg to enable timestamps.

I'm happy with this but find the documentation confusing.

> diff --git a/util/qemu-time.c b/util/qemu-time.c
> new file mode 100644
> index 0000000..3862788
> --- /dev/null
> +++ b/util/qemu-time.c
> @@ -0,0 +1,26 @@
> +/*
> + * Time handling
> + *
> + * Copyright (C) 2013 Hitachi Data Systems Corp.
> + *
> + * Authors:
> + *  Seiji Aguchi <sei...@hd...>
> + *
> + * This work is licensed under the terms of the GNU GPL, version 2 or later.
> + * See the COPYING file in the top-level directory.
> + */
> +#include "qemu/time.h"
> +
> +void qemu_get_timestamp_str(char *timestr, size_t len)
> +{
> +    GTimeVal tv;
> +    gchar *tmp_str = NULL;
> +
> +    /* Size of len should be at least TIMESTAMP_LEN to avoid truncation */
> +    assert(len >= TIMESTAMP_LEN);
> +
> +    g_get_current_time(&tv);
> +    tmp_str = g_time_val_to_iso8601(&tv);
> +    g_strlcpy((gchar *)timestr, tmp_str, len);
> +    g_free(tmp_str);
> +}

Why strcpy into a fixed-size buffer when glib gives us a heap-allocated
string?

This patch would be simpler by dropping qemu-time.c/time.h and simply
doing:

if (enable_timestamp_msg) {
    GTimeVal tv;
    gchar *timestamp;

    g_get_current_time(&tv);
    timestamp = g_time_val_to_iso8601(&tv);
    error_printf("%s ", timestamp);
    g_free(timestamp);
}

Re: [Dle-develop] [PATCH v5] Add timestamp to error_report()

[Laszlo E. <le...@re...>]

On 07/01/13 20:54, Seiji Aguchi wrote:
> [Issue]
> When we offer a customer support service and a problem happens
> in a customer's system, we try to understand the problem by
> comparing what the customer reports with message logs of the
> customer's system.
> 
> In this case, we often need to know when the problem happens.
> 
> But, currently, there is no timestamp in qemu's error messages.
> Therefore, we may not be able to understand the problem based on
> error messages.
> 
> [Solution]
> Add a timestamp to qemu's error message logged by
> error_report() with g_time_val_to_iso8601().
> 
> Signed-off-by: Seiji Aguchi <sei...@hd...>
> ---
> Changelog
>  v4 -> v5
>  - Use sizeof() to define TIMESTAMP_LEN.
>  - Fix descriptions of msg option.
>  - Rename TIME_H to QEMU_TIME_H. (avoiding double inclusion of qemu/time.h)
>  - Change argument of qemu_get_timestamp_str to "char *" and "size_t".
>  - Confirmed msg option is displayed by query-command-line-options.

Reviewed-by: Laszlo Ersek <le...@re...>

Since you plan to post followup patches, please at that time include a
one-liner modification: the STEXI-ETEXI section in "qemu-options.hx"
still says (right before ETEXI) "(disabled by default)". I think it
should be fixed in a followup, not by posting v6.

Thanks!
Laszlo

Re: [Dle-develop] [Qemu-devel] [PATCH v4] Add timestamp to error message

[Seiji A. <sei...@hd...>]

> > >  void error_report(const char *fmt, ...)
> > >  {
> > >      va_list ap;
> > > +    char timestr[TIMESTAMP_LEN];
> > > +
> > > +    if (enable_timestamp_msg) {
> > > +        qemu_get_timestamp_str(&timestr);
> > > +        error_printf("%s ", timestr);
> > > +    }
> > >
> > >      error_print_loc();
> > >      va_start(ap, fmt);
> >
> > Does this print the timestamp to all kinds of monitors too? On stderr,
> > the timestamp is great. When printed to an "interactive monitor", it
> > could also help post-mortem debugging. But would it not confuse libvirt
> > eg.? (Apologies if this has been discussed before.)
> 
> I will try to add timestamp to monitor_printf().
> (In the long term, I would like to add it to all fprintf() in qemu.)

I tried to add timestamp to monitor_printf().
But, it wasn't easier than I expected.
(At least, we should not add it to monitor_printf() in readline.c.)
We need to discuss which message of monitor_printf() has to be
added timestamp.

Therefore, I would like to forcus on error_report() in this thread.
(I posted patch v5 just now.)

Seiji

[Dle-develop] [PATCH v5] Add timestamp to error_report()

[Seiji A. <sei...@hd...>]

[Issue]
When we offer a customer support service and a problem happens
in a customer's system, we try to understand the problem by
comparing what the customer reports with message logs of the
customer's system.

In this case, we often need to know when the problem happens.

But, currently, there is no timestamp in qemu's error messages.
Therefore, we may not be able to understand the problem based on
error messages.

[Solution]
Add a timestamp to qemu's error message logged by
error_report() with g_time_val_to_iso8601().

Signed-off-by: Seiji Aguchi <sei...@hd...>
---
Changelog
 v4 -> v5
 - Use sizeof() to define TIMESTAMP_LEN.
 - Fix descriptions of msg option.
 - Rename TIME_H to QEMU_TIME_H. (avoiding double inclusion of qemu/time.h)
 - Change argument of qemu_get_timestamp_str to "char *" and "size_t".
 - Confirmed msg option is displayed by query-command-line-options.

 v3 -> v4
 - Correct email address of Signed-off-by.

 v2 -> v3
 - Use g_time_val_to_iso8601() to get timestamp instead of
   copying libvirt's time-handling functions.

   According to discussion below, qemu doesn't need to take care
   if timestamp functions are async-signal safe or not.

   http://marc.info/?l=qemu-devel&m=136741841921265&w=2

   Also, In the review of v2 patch, strftime() are recommended to
   format string. But it is not a suitable function to handle msec.

   Then, simply call g_time_val_to_iso8601().

 - Intoroduce a common time-handling function to util/qemu-time.c.
   (Suggested by Daniel P. Berrange)

 - Add testing for g_time_val_to_iso8601() to tests/test-time.c.
   The test cases are copied from libvirt's virtimetest.
   (Suggested by Daniel P. Berrange)

 v1 -> v2

 - add an option, -msg timestamp={on|off}, to enable output message with timestamp
---
 include/qemu/time.h |   10 ++++++++++
 qemu-options.hx     |   12 ++++++++++++
 util/Makefile.objs  |    1 +
 util/qemu-error.c   |    8 ++++++++
 util/qemu-time.c    |   26 ++++++++++++++++++++++++++
 vl.c                |   28 ++++++++++++++++++++++++++++
 6 files changed, 85 insertions(+), 0 deletions(-)
 create mode 100644 include/qemu/time.h
 create mode 100644 util/qemu-time.c

diff --git a/include/qemu/time.h b/include/qemu/time.h
new file mode 100644
index 0000000..ce3903e
--- /dev/null
+++ b/include/qemu/time.h
@@ -0,0 +1,10 @@
+#ifndef QEMU_TIME_H
+#define QEMU_TIME_H
+
+#include "qemu-common.h"
+
+#define TIMESTAMP_LEN sizeof("1970-01-01T00:00:00.999999Z")
+extern void qemu_get_timestamp_str(char *, size_t);
+extern bool enable_timestamp_msg;
+
+#endif /* QEMU_TIME_H */
diff --git a/qemu-options.hx b/qemu-options.hx
index ca6fdf6..a6dac1a 100644
--- a/qemu-options.hx
+++ b/qemu-options.hx
@@ -3102,3 +3102,15 @@ HXCOMM This is the last statement. Insert new options before this line!
 STEXI
 @end table
 ETEXI
+
+DEF("msg", HAS_ARG, QEMU_OPTION_msg,
+    "-msg [timestamp=on|off]\n"
+    "  change the format of messages\n"
+    "  timestamp=on|off enables leading timestamps (default:on)\n",
+    QEMU_ARCH_ALL)
+STEXI
+@item -msg timestamp=on|off
+@findex -msg
+prepend a timestamp to each log message.
+(disabled by default)
+ETEXI
diff --git a/util/Makefile.objs b/util/Makefile.objs
index dc72ab0..063db56 100644
--- a/util/Makefile.objs
+++ b/util/Makefile.objs
@@ -11,3 +11,4 @@ util-obj-y += iov.o aes.o qemu-config.o qemu-sockets.o uri.o notify.o
 util-obj-y += qemu-option.o qemu-progress.o
 util-obj-y += hexdump.o
 util-obj-y += crc32c.o
+util-obj-y += qemu-time.o
diff --git a/util/qemu-error.c b/util/qemu-error.c
index 08a36f4..c65fdfd 100644
--- a/util/qemu-error.c
+++ b/util/qemu-error.c
@@ -12,6 +12,7 @@
 
 #include <stdio.h>
 #include "monitor/monitor.h"
+#include "qemu/time.h"
 
 /*
  * Print to current monitor if we have one, else to stderr.
@@ -196,6 +197,7 @@ void error_print_loc(void)
     }
 }
 
+bool enable_timestamp_msg;
 /*
  * Print an error message to current monitor if we have one, else to stderr.
  * Format arguments like sprintf().  The result should not contain
@@ -206,6 +208,12 @@ void error_print_loc(void)
 void error_report(const char *fmt, ...)
 {
     va_list ap;
+    char timestr[TIMESTAMP_LEN];
+
+    if (enable_timestamp_msg) {
+        qemu_get_timestamp_str(timestr, sizeof(timestr));
+        error_printf("%s ", timestr);
+    }
 
     error_print_loc();
     va_start(ap, fmt);
diff --git a/util/qemu-time.c b/util/qemu-time.c
new file mode 100644
index 0000000..3862788
--- /dev/null
+++ b/util/qemu-time.c
@@ -0,0 +1,26 @@
+/*
+ * Time handling
+ *
+ * Copyright (C) 2013 Hitachi Data Systems Corp.
+ *
+ * Authors:
+ *  Seiji Aguchi <sei...@hd...>
+ *
+ * This work is licensed under the terms of the GNU GPL, version 2 or later.
+ * See the COPYING file in the top-level directory.
+ */
+#include "qemu/time.h"
+
+void qemu_get_timestamp_str(char *timestr, size_t len)
+{
+    GTimeVal tv;
+    gchar *tmp_str = NULL;
+
+    /* Size of len should be at least TIMESTAMP_LEN to avoid truncation */
+    assert(len >= TIMESTAMP_LEN);
+
+    g_get_current_time(&tv);
+    tmp_str = g_time_val_to_iso8601(&tv);
+    g_strlcpy((gchar *)timestr, tmp_str, len);
+    g_free(tmp_str);
+}
diff --git a/vl.c b/vl.c
index 0a8f056..aee7350 100644
--- a/vl.c
+++ b/vl.c
@@ -171,6 +171,8 @@ int main(int argc, char **argv)
 #include "ui/qemu-spice.h"
 #include "qapi/string-input-visitor.h"
 
+#include "qemu/time.h"
+
 //#define DEBUG_NET
 //#define DEBUG_SLIRP
 
@@ -516,6 +518,18 @@ static QemuOptsList qemu_realtime_opts = {
     },
 };
 
+static QemuOptsList qemu_msg_opts = {
+    .name = "msg",
+    .head = QTAILQ_HEAD_INITIALIZER(qemu_msg_opts.head),
+    .desc = {
+        {
+            .name = "timestamp",
+            .type = QEMU_OPT_BOOL,
+        },
+        { /* end of list */ }
+    },
+};
+
 const char *qemu_get_vm_name(void)
 {
     return qemu_name;
@@ -1459,6 +1473,12 @@ static void configure_realtime(QemuOpts *opts)
     }
 }
 
+
+static void configure_msg(QemuOpts *opts)
+{
+    enable_timestamp_msg = qemu_opt_get_bool(opts, "timestamp", true);
+}
+
 /***********************************************************/
 /* USB devices */
 
@@ -2901,6 +2921,7 @@ int main(int argc, char **argv, char **envp)
     qemu_add_opts(&qemu_object_opts);
     qemu_add_opts(&qemu_tpmdev_opts);
     qemu_add_opts(&qemu_realtime_opts);
+    qemu_add_opts(&qemu_msg_opts);
 
     runstate_init();
 
@@ -3808,6 +3829,13 @@ int main(int argc, char **argv, char **envp)
                 }
                 configure_realtime(opts);
                 break;
+            case QEMU_OPTION_msg:
+                opts = qemu_opts_parse(qemu_find_opts("msg"), optarg, 0);
+                if (!opts) {
+                    exit(1);
+                }
+                configure_msg(opts);
+                break;
             default:
                 os_parse_cmd_args(popt->index, optarg);
             }
-- 1.7.1 

Re: [Dle-develop] [Qemu-devel] [PATCH v4] Add timestamp to error message

[Seiji A. <sei...@hd...>]

> >>
> >> I wonder if TIME_H is maybe a bit too nondescript and could conflict
> >> with other guards.

OK.
I will use QEMU_TIME_H.
Apologies for my curt reply.

Seiji

Re: [Dle-develop] [Qemu-devel] [PATCH v4] Add timestamp to error message

[Laszlo E. <le...@re...>]

On 06/28/13 20:54, Seiji Aguchi wrote:
> 
>>> diff --git a/include/qemu/time.h b/include/qemu/time.h
>>> new file mode 100644
>>> index 0000000..f70739b
>>> --- /dev/null
>>> +++ b/include/qemu/time.h
>>> @@ -0,0 +1,11 @@
>>> +#ifndef TIME_H
>>> +#define TIME_H
>>
>> I wonder if TIME_H is maybe a bit too nondescript and could conflict
>> with other guards.
>>
>> The guards currently used in "include/qemu/*.h" files are inconsistent
>> -- some use a QEMU_ prefix, some a __QEMU_ one, and others use none.
>>
>> Don't respin just because of this, but maybe it's something to consider.
> 
> This should be discussed in other thread...

Ah, right, apologies for the ambiguity. I just meant that either
QEMU_TIME_H or __QEMU_TIME_H would have a lower chance to clash with
another guard than plain TIME_H -- "some" prefix would be nice, but I
couldn't point out a specific one, because the current practice varies.
I didn't mean to suggest that you should unify the prefixes across all
guards!

Anyway, even my QEMU_TIME_H / __QEMU_TIME_H suggestion is tangential;
feel free to ignore it.

Thanks
Laszlo

Re: [Dle-develop] [PATCH v3] Add timestamp to error message

[Seiji A. <sei...@hd...>]

Thank you for the review.

> > +#include "qemu-common.h"
> > +
> > +/*  "1970-01-01T00:00:00.999999Z" + '\0' */
> > +#define TIMESTAMP_LEN 28
> 
> Self-documenting constants are nicer:
> 
> #define TIMESTAMP_LEN (sizeof("1970-01-01T00:00:00.999999Z")+1)

I will fix it.

> 
> extern void qemu_get_timestamp_str(char *timestr, size_t len)
> 
> where len is the length of timestr, and where the comments document that
> len should be at least TIMESTAMP_LEN to avoid truncation (or even
> assert() if it is not)?

I will fix as above.

> 
> > +++ b/qemu-options.hx
> > @@ -3102,3 +3102,15 @@ HXCOMM This is the last statement. Insert new options before this line!
> >  STEXI
> >  @end table
> >  ETEXI
> > +
> > +DEF("msg", HAS_ARG, QEMU_OPTION_msg,
> > +    "-msg [timestamp=on|off]\n"
> > +    "                output message with timestamp (default: off)\n",
> > +    QEMU_ARCH_ALL)
> 
> Did you test that the existing query-command-line-options QMP command
> will list this option (just making sure that libvirt will be able to
> know when to use this option).

I will test it in the next patch.

Seiji

> 
> --
> Eric Blake   eblake redhat com    +1-919-301-3266
> Libvirt virtualization library http://libvirt.org

Re: [Dle-develop] [Qemu-devel] [PATCH v4] Add timestamp to error message

[Seiji A. <sei...@hd...>]

> > diff --git a/include/qemu/time.h b/include/qemu/time.h
> > new file mode 100644
> > index 0000000..f70739b
> > --- /dev/null
> > +++ b/include/qemu/time.h
> > @@ -0,0 +1,11 @@
> > +#ifndef TIME_H
> > +#define TIME_H
> 
> I wonder if TIME_H is maybe a bit too nondescript and could conflict
> with other guards.
> 
> The guards currently used in "include/qemu/*.h" files are inconsistent
> -- some use a QEMU_ prefix, some a __QEMU_ one, and others use none.
> 
> Don't respin just because of this, but maybe it's something to consider.

This should be discussed in other thread...

> 
> 
> > +
> > +#include "qemu-common.h"
> > +
> > +/*  "1970-01-01T00:00:00.999999Z" + '\0' */
> > +#define TIMESTAMP_LEN 28
> > +extern void qemu_get_timestamp_str(char (*timestr)[]);

I will change to "extern void qemu_get_timestamp_str(char *timestr, size_t len)"
as Eric pointed out.

> 
> 
> > +extern bool enable_timestamp_msg;
> > +
> > +#endif /* !TIME_H */
> > diff --git a/qemu-options.hx b/qemu-options.hx
> > index ca6fdf6..7890921 100644
> > --- a/qemu-options.hx
> > +++ b/qemu-options.hx
> > @@ -3102,3 +3102,15 @@ HXCOMM This is the last statement. Insert new options before this line!
> >  STEXI
> >  @end table
> >  ETEXI
> > +
> > +DEF("msg", HAS_ARG, QEMU_OPTION_msg,
> > +    "-msg [timestamp=on|off]\n"
> > +    "                output message with timestamp (default: off)\n",
> > +    QEMU_ARCH_ALL)
> > +STEXI
> > +@item -msg timestamp=on|off
> > +@findex - msg
> 
> A space has snuck in between "-" and "msg". Perhaps this is the only
> note that would warrant a respin (or rather a maintainer fixup at commit).

I will fix it.

> 
> 
> > +Output message with timestamp.
> 
> As a non-native speaker, I propose rewording this as "prepend a
> timestamp to each log message" (in the prior occurrence as well) if you
> decided to repost.

Will fix as well.

> >  void error_report(const char *fmt, ...)
> >  {
> >      va_list ap;
> > +    char timestr[TIMESTAMP_LEN];
> > +
> > +    if (enable_timestamp_msg) {
> > +        qemu_get_timestamp_str(&timestr);
> > +        error_printf("%s ", timestr);
> > +    }
> >
> >      error_print_loc();
> >      va_start(ap, fmt);
> 
> Does this print the timestamp to all kinds of monitors too? On stderr,
> the timestamp is great. When printed to an "interactive monitor", it
> could also help post-mortem debugging. But would it not confuse libvirt
> eg.? (Apologies if this has been discussed before.)

I will try to add timestamp to monitor_printf().
(In the long term, I would like to add it to all fprintf() in qemu.)

> 
> 
> > diff --git a/util/qemu-time.c b/util/qemu-time.c
> > new file mode 100644
> > index 0000000..37f7b9e
> > --- /dev/null
> > +++ b/util/qemu-time.c
> > @@ -0,0 +1,24 @@
> > +/*
> > + * Time handling
> > + *
> > + * Copyright (C) 2013 Hitachi Data Systems Corp.
> > + *
> > + * Authors:
> > + *  Seiji Aguchi <sei...@hd...>
> > + *
> > + * This work is licensed under the terms of the GNU GPL, version 2 or later.
> > + * See the COPYING file in the top-level directory.
> > + */
> > +#include "qemu/time.h"
> > +
> > +void qemu_get_timestamp_str(char (*timestr)[])
> > +{
> > +    GTimeVal tv;
> > +    gchar *tmp_str = NULL;
> > +
> > +    g_get_current_time(&tv);
> 
> Hm. There's also g_get_monotonic_time(), but (a) that's less portable
> (available since 2.28), (b) this is simply good enough IMO, in practice. OK.
> 
> 
> > +    tmp_str = g_time_val_to_iso8601(&tv);
> > +    g_strlcpy((gchar *)*timestr, tmp_str, TIMESTAMP_LEN);
> > +    g_free(tmp_str);
> > +    return;
> 
> You're not returning a value so the last statement is superfluous.

I will remove the unnecessary "return".

> > +
> > +static void configure_msg(QemuOpts *opts)
> > +{
> > +    enable_timestamp_msg = qemu_opt_get_bool(opts, "timestamp", true);
> > +}
> 
> I think the default value doesn't match the docs, which say "deafult:
> off". As far as I recall (from Tomoki's "-realtime [mlock=on|off]"
> patch), statements about defaults in the option docs don't describe how
> qemu works by default (ie. when you omit the option altogether), they
> describe what happens if you specify the option but omit its arguments
> (ie. with "-msg" only.)
> 
> In that case, the docs should state something like:
> 
> DEF("msg", HAS_ARG, QEMU_OPTION_msg,
>     "-msg [timestamp=on|off]\n"
>     "     change the format of error messages\n"
>     "     timestamp=on|off enables leading timestamps (default: on)\n",
>     QEMU_ARCH_ALL)

Currently, this patch add timestamp to just error_report().
But, we may need it for both error and normal messages.
So, I will change the sentence "change the format of error messages"
to "change the format of messages".

I appreciate your review.

Seiji

Re: [Dle-develop] [Qemu-devel] [PATCH v4] Add timestamp to error message

[Eric B. <eb...@re...>]

On 06/27/2013 04:21 AM, Laszlo Ersek wrote:
> comments below
> 
> On 06/27/13 04:08, Seiji Aguchi wrote:
>> [Issue]
>> When we offer a customer support service and a problem happens
>> in a customer's system, we try to understand the problem by
>> comparing what the customer reports with message logs of the
>> customer's system.
>>

>> +extern void qemu_get_timestamp_str(char (*timestr)[]);
> 
> (a) The type of "timestr" is a valid one, it says "pointer to array of
> unknown size". The array type is an incomplete type (its size is
> unknown), but pointers can point to incomplete types (like to an opaque
> struct, which is also an incomplete type).
> 
> It's however quite unusual to write something like this, when a simple
> pointer-to-char would do.

Agreed; I made a similar comment against v3.

>>      error_print_loc();
>>      va_start(ap, fmt);
> 
> Does this print the timestamp to all kinds of monitors too? On stderr,
> the timestamp is great. When printed to an "interactive monitor", it
> could also help post-mortem debugging. But would it not confuse libvirt
> eg.? (Apologies if this has been discussed before.)

Libvirt would love to unconditionally enable timestamps in log output;
having coordination of any qemu log dumped alongside other libvirt log
output will indeed benefit from having a common timestamp synchronization.

Regarding monitor output, libvirt uses the QMP monitor, not the HMP
monitor, and this had better not prepend text to QMP output (since that
would result in non-JSON output).  It could be added as an additional
dictionary member within each QMP command, which would not impact
libvirt (which ignores dictionary elements it is not expecting, or
future libvirt could see if a timestamp was passed back).  HMP
passthrough commands called via QMP's 'human-monitor-command' might then
have the timestamp included, but that's not an issue since HMP output is
already not guaranteed stable.  But if you DO want to add it to QMP
return values, then it needs a followup patch.

-- 
Eric Blake   eblake redhat com    +1-919-301-3266
Libvirt virtualization library http://libvirt.org

Re: [Dle-develop] [PATCH v3] Add timestamp to error message

[Eric B. <eb...@re...>]

On 06/26/2013 04:20 PM, Seiji Aguchi wrote:
> [Issue]
> When we offer a customer support service and a problem happens
> in a customer's system, we try to understand the problem by
> comparing what the customer reports with message logs of the
> customer's system.
> 

> +#include "qemu-common.h"
> +
> +/*  "1970-01-01T00:00:00.999999Z" + '\0' */
> +#define TIMESTAMP_LEN 28

Self-documenting constants are nicer:

#define TIMESTAMP_LEN (sizeof("1970-01-01T00:00:00.999999Z")+1)

> +extern void qemu_get_timestamp_str(char (*timestr)[]);

Eww.  I had a tough time parsing this signature.  Isn't it the same as
the more legible:

extern void qemu_get_timestamp_str(char **timestr);

Furthermore, isn't the idea that you DON'T want to return a malloc'd
string, but require that the user pre-allocate storage that we write
into (since malloc during a log message reporting OOM is liable to fail,
but we still want the log to be best effort)?  But then why do you need
a pointer to an array?  Wouldn't it be better as:

extern void qemu_get_timestamp_str(char *timestr, size_t len)

where len is the length of timestr, and where the comments document that
len should be at least TIMESTAMP_LEN to avoid truncation (or even
assert() if it is not)?

> +++ b/qemu-options.hx
> @@ -3102,3 +3102,15 @@ HXCOMM This is the last statement. Insert new options before this line!
>  STEXI
>  @end table
>  ETEXI
> +
> +DEF("msg", HAS_ARG, QEMU_OPTION_msg,
> +    "-msg [timestamp=on|off]\n"
> +    "                output message with timestamp (default: off)\n",
> +    QEMU_ARCH_ALL)

Did you test that the existing query-command-line-options QMP command
will list this option (just making sure that libvirt will be able to
know when to use this option).

-- 
Eric Blake   eblake redhat com    +1-919-301-3266
Libvirt virtualization library http://libvirt.org

Re: [Dle-develop] [Qemu-devel] [PATCH v4] Add timestamp to error message

[Laszlo E. <le...@re...>]

comments below

On 06/27/13 04:08, Seiji Aguchi wrote:
> [Issue]
> When we offer a customer support service and a problem happens
> in a customer's system, we try to understand the problem by
> comparing what the customer reports with message logs of the
> customer's system.
> 
> In this case, we often need to know when the problem happens.
> 
> But, currently, there is no timestamp in qemu's error messages.
> Therefore, we may not be able to understand the problem based on
> error messages.
> 
> [Solution]
> Add a timestamp to qemu's error message logged by
> error_report() with g_time_val_to_iso8601().
> 
> [TODO]
> Add timestamp to monitor_printf() and fprintf().
> 
> Signed-off-by: Seiji Aguchi <sei...@hd...>
> ---
> Changelog
>  v3 -> v4
>  - Correct email address of Signed-off-by.
> 
>  v2 -> v3
> 
>  - Use g_time_val_to_iso8601() to get timestamp instead of
>    copying libvirt's time-handling functions.
> 
>    According to discussion below, qemu doesn't need to take care
>    if timestamp functions are async-signal safe or not.
> 
>    http://marc.info/?l=qemu-devel&m=136741841921265&w=2
> 
>    Also, In the review of v2 patch, strftime() are recommended to
>    format string. But it is not a suitable function to handle msec.
> 
>    Then, simply call g_time_val_to_iso8601().

I think this is a good choice. Based on the glib NEWS file, the latest
fix for g_time_val_to_iso8601() went into 2.19.6. Therefore the function
should be available on stable distros (eg. RHEL-6 has glib2-2.22.5-7.el6).

> 
>  - Intoroduce a common time-handling function to util/qemu-time.c.
>    (Suggested by Daniel P. Berrange)
> 
>  v1 -> v2
> 
>  - add an option, -msg timestamp={on|off}, to enable output message with timestamp
> ---
>  include/qemu/time.h |   11 +++++++++++
>  qemu-options.hx     |   12 ++++++++++++
>  util/Makefile.objs  |    1 +
>  util/qemu-error.c   |    8 ++++++++
>  util/qemu-time.c    |   24 ++++++++++++++++++++++++
>  vl.c                |   28 ++++++++++++++++++++++++++++
>  6 files changed, 84 insertions(+), 0 deletions(-)
>  create mode 100644 include/qemu/time.h
>  create mode 100644 util/qemu-time.c
> 
> diff --git a/include/qemu/time.h b/include/qemu/time.h
> new file mode 100644
> index 0000000..f70739b
> --- /dev/null
> +++ b/include/qemu/time.h
> @@ -0,0 +1,11 @@
> +#ifndef TIME_H
> +#define TIME_H

I wonder if TIME_H is maybe a bit too nondescript and could conflict
with other guards.

The guards currently used in "include/qemu/*.h" files are inconsistent
-- some use a QEMU_ prefix, some a __QEMU_ one, and others use none.

Don't respin just because of this, but maybe it's something to consider.


> +
> +#include "qemu-common.h"
> +
> +/*  "1970-01-01T00:00:00.999999Z" + '\0' */
> +#define TIMESTAMP_LEN 28
> +extern void qemu_get_timestamp_str(char (*timestr)[]);

(a) The type of "timestr" is a valid one, it says "pointer to array of
unknown size". The array type is an incomplete type (its size is
unknown), but pointers can point to incomplete types (like to an opaque
struct, which is also an incomplete type).

It's however quite unusual to write something like this, when a simple
pointer-to-char would do. The above prototype requres any caller that
wants to format the timestamp into the middle of an array to typecasting
hackery. Compare:

{
    char buf[1024];

    /* I want the timestamp to start at the fifth element */
    qemu_get_timestamp_str((char (*)[1020])(buf + 4));
}

vs.

{
    char buf[1024];

    qemu_get_timestamp_str(buf + 4);
}

(b) Also, although it's correct C, we avoid the "extern" storage-class
specifier for function declarations in file scope. ("extern" is called a
storage-class specifier for syntax reasons, in fact it determines
linkage for the function of course.)

(c) Third suggestion for the prototype: since it can never fail, make it
return the "timestr" pointer just passed in. That would allow use such as:

{
    char buf[TIMESTAMP_LEN];

    printf("[%s] hello world!\n", qemu_get_timestamp_str(buf));
}

None of this is important of course :) The one call to this function is
nicely buried in practice, and the bikeshedding has been going on for
too long for this patch.


> +extern bool enable_timestamp_msg;
> +
> +#endif /* !TIME_H */
> diff --git a/qemu-options.hx b/qemu-options.hx
> index ca6fdf6..7890921 100644
> --- a/qemu-options.hx
> +++ b/qemu-options.hx
> @@ -3102,3 +3102,15 @@ HXCOMM This is the last statement. Insert new options before this line!
>  STEXI
>  @end table
>  ETEXI
> +
> +DEF("msg", HAS_ARG, QEMU_OPTION_msg,
> +    "-msg [timestamp=on|off]\n"
> +    "                output message with timestamp (default: off)\n",
> +    QEMU_ARCH_ALL)
> +STEXI
> +@item -msg timestamp=on|off
> +@findex - msg

A space has snuck in between "-" and "msg". Perhaps this is the only
note that would warrant a respin (or rather a maintainer fixup at commit).


> +Output message with timestamp.

As a non-native speaker, I propose rewording this as "prepend a
timestamp to each log message" (in the prior occurrence as well) if you
decided to repost.


> +Adding timestamp to messages with @option{timestamp=on}
> +(disabled by default).
> +ETEXI
> diff --git a/util/Makefile.objs b/util/Makefile.objs
> index dc72ab0..063db56 100644
> --- a/util/Makefile.objs
> +++ b/util/Makefile.objs
> @@ -11,3 +11,4 @@ util-obj-y += iov.o aes.o qemu-config.o qemu-sockets.o uri.o notify.o
>  util-obj-y += qemu-option.o qemu-progress.o
>  util-obj-y += hexdump.o
>  util-obj-y += crc32c.o
> +util-obj-y += qemu-time.o
> diff --git a/util/qemu-error.c b/util/qemu-error.c
> index 08a36f4..33fa9d3 100644
> --- a/util/qemu-error.c
> +++ b/util/qemu-error.c
> @@ -12,6 +12,7 @@
>  
>  #include <stdio.h>
>  #include "monitor/monitor.h"
> +#include "qemu/time.h"
>  
>  /*
>   * Print to current monitor if we have one, else to stderr.
> @@ -196,6 +197,7 @@ void error_print_loc(void)
>      }
>  }
>  
> +bool enable_timestamp_msg;
>  /*
>   * Print an error message to current monitor if we have one, else to stderr.
>   * Format arguments like sprintf().  The result should not contain
> @@ -206,6 +208,12 @@ void error_print_loc(void)
>  void error_report(const char *fmt, ...)
>  {
>      va_list ap;
> +    char timestr[TIMESTAMP_LEN];
> +
> +    if (enable_timestamp_msg) {
> +        qemu_get_timestamp_str(&timestr);
> +        error_printf("%s ", timestr);
> +    }
>  
>      error_print_loc();
>      va_start(ap, fmt);

Does this print the timestamp to all kinds of monitors too? On stderr,
the timestamp is great. When printed to an "interactive monitor", it
could also help post-mortem debugging. But would it not confuse libvirt
eg.? (Apologies if this has been discussed before.)


> diff --git a/util/qemu-time.c b/util/qemu-time.c
> new file mode 100644
> index 0000000..37f7b9e
> --- /dev/null
> +++ b/util/qemu-time.c
> @@ -0,0 +1,24 @@
> +/*
> + * Time handling
> + *
> + * Copyright (C) 2013 Hitachi Data Systems Corp.
> + *
> + * Authors:
> + *  Seiji Aguchi <sei...@hd...>
> + *
> + * This work is licensed under the terms of the GNU GPL, version 2 or later.
> + * See the COPYING file in the top-level directory.
> + */
> +#include "qemu/time.h"
> +
> +void qemu_get_timestamp_str(char (*timestr)[])
> +{
> +    GTimeVal tv;
> +    gchar *tmp_str = NULL;
> +
> +    g_get_current_time(&tv);

Hm. There's also g_get_monotonic_time(), but (a) that's less portable
(available since 2.28), (b) this is simply good enough IMO, in practice. OK.


> +    tmp_str = g_time_val_to_iso8601(&tv);
> +    g_strlcpy((gchar *)*timestr, tmp_str, TIMESTAMP_LEN);
> +    g_free(tmp_str);
> +    return;

You're not returning a value so the last statement is superfluous.

> +}
> diff --git a/vl.c b/vl.c
> index 0a8f056..aee7350 100644
> --- a/vl.c
> +++ b/vl.c
> @@ -171,6 +171,8 @@ int main(int argc, char **argv)
>  #include "ui/qemu-spice.h"
>  #include "qapi/string-input-visitor.h"
>  
> +#include "qemu/time.h"
> +
>  //#define DEBUG_NET
>  //#define DEBUG_SLIRP
>  
> @@ -516,6 +518,18 @@ static QemuOptsList qemu_realtime_opts = {
>      },
>  };
>  
> +static QemuOptsList qemu_msg_opts = {
> +    .name = "msg",
> +    .head = QTAILQ_HEAD_INITIALIZER(qemu_msg_opts.head),
> +    .desc = {
> +        {
> +            .name = "timestamp",
> +            .type = QEMU_OPT_BOOL,
> +        },
> +        { /* end of list */ }
> +    },
> +};
> +
>  const char *qemu_get_vm_name(void)
>  {
>      return qemu_name;
> @@ -1459,6 +1473,12 @@ static void configure_realtime(QemuOpts *opts)
>      }
>  }
>  
> +
> +static void configure_msg(QemuOpts *opts)
> +{
> +    enable_timestamp_msg = qemu_opt_get_bool(opts, "timestamp", true);
> +}

I think the default value doesn't match the docs, which say "deafult:
off". As far as I recall (from Tomoki's "-realtime [mlock=on|off]"
patch), statements about defaults in the option docs don't describe how
qemu works by default (ie. when you omit the option altogether), they
describe what happens if you specify the option but omit its arguments
(ie. with "-msg" only.)

In that case, the docs should state something like:

DEF("msg", HAS_ARG, QEMU_OPTION_msg,
    "-msg [timestamp=on|off]\n"
    "     change the format of error messages\n"
    "     timestamp=on|off enables leading timestamps (default: on)\n",
    QEMU_ARCH_ALL)

> +
>  /***********************************************************/
>  /* USB devices */
>  
> @@ -2901,6 +2921,7 @@ int main(int argc, char **argv, char **envp)
>      qemu_add_opts(&qemu_object_opts);
>      qemu_add_opts(&qemu_tpmdev_opts);
>      qemu_add_opts(&qemu_realtime_opts);
> +    qemu_add_opts(&qemu_msg_opts);
>  
>      runstate_init();
>  
> @@ -3808,6 +3829,13 @@ int main(int argc, char **argv, char **envp)
>                  }
>                  configure_realtime(opts);
>                  break;
> +            case QEMU_OPTION_msg:
> +                opts = qemu_opts_parse(qemu_find_opts("msg"), optarg, 0);
> +                if (!opts) {
> +                    exit(1);
> +                }
> +                configure_msg(opts);
> +                break;
>              default:
>                  os_parse_cmd_args(popt->index, optarg);
>              }
> 

I hope you don't mind my review.

Thanks,
Laszlo

[Dle-develop] [PATCH v4] Add timestamp to error message

[Seiji A. <sei...@hd...>]

[Issue]
When we offer a customer support service and a problem happens
in a customer's system, we try to understand the problem by
comparing what the customer reports with message logs of the
customer's system.

In this case, we often need to know when the problem happens.

But, currently, there is no timestamp in qemu's error messages.
Therefore, we may not be able to understand the problem based on
error messages.

[Solution]
Add a timestamp to qemu's error message logged by
error_report() with g_time_val_to_iso8601().

[TODO]
Add timestamp to monitor_printf() and fprintf().

Signed-off-by: Seiji Aguchi <sei...@hd...>
---
Changelog
 v3 -> v4
 - Correct email address of Signed-off-by.

 v2 -> v3

 - Use g_time_val_to_iso8601() to get timestamp instead of
   copying libvirt's time-handling functions.

   According to discussion below, qemu doesn't need to take care
   if timestamp functions are async-signal safe or not.

   http://marc.info/?l=qemu-devel&m=136741841921265&w=2

   Also, In the review of v2 patch, strftime() are recommended to
   format string. But it is not a suitable function to handle msec.

   Then, simply call g_time_val_to_iso8601().

 - Intoroduce a common time-handling function to util/qemu-time.c.
   (Suggested by Daniel P. Berrange)

 v1 -> v2

 - add an option, -msg timestamp={on|off}, to enable output message with timestamp
---
 include/qemu/time.h |   11 +++++++++++
 qemu-options.hx     |   12 ++++++++++++
 util/Makefile.objs  |    1 +
 util/qemu-error.c   |    8 ++++++++
 util/qemu-time.c    |   24 ++++++++++++++++++++++++
 vl.c                |   28 ++++++++++++++++++++++++++++
 6 files changed, 84 insertions(+), 0 deletions(-)
 create mode 100644 include/qemu/time.h
 create mode 100644 util/qemu-time.c

diff --git a/include/qemu/time.h b/include/qemu/time.h
new file mode 100644
index 0000000..f70739b
--- /dev/null
+++ b/include/qemu/time.h
@@ -0,0 +1,11 @@
+#ifndef TIME_H
+#define TIME_H
+
+#include "qemu-common.h"
+
+/*  "1970-01-01T00:00:00.999999Z" + '\0' */
+#define TIMESTAMP_LEN 28
+extern void qemu_get_timestamp_str(char (*timestr)[]);
+extern bool enable_timestamp_msg;
+
+#endif /* !TIME_H */
diff --git a/qemu-options.hx b/qemu-options.hx
index ca6fdf6..7890921 100644
--- a/qemu-options.hx
+++ b/qemu-options.hx
@@ -3102,3 +3102,15 @@ HXCOMM This is the last statement. Insert new options before this line!
 STEXI
 @end table
 ETEXI
+
+DEF("msg", HAS_ARG, QEMU_OPTION_msg,
+    "-msg [timestamp=on|off]\n"
+    "                output message with timestamp (default: off)\n",
+    QEMU_ARCH_ALL)
+STEXI
+@item -msg timestamp=on|off
+@findex - msg
+Output message with timestamp.
+Adding timestamp to messages with @option{timestamp=on}
+(disabled by default).
+ETEXI
diff --git a/util/Makefile.objs b/util/Makefile.objs
index dc72ab0..063db56 100644
--- a/util/Makefile.objs
+++ b/util/Makefile.objs
@@ -11,3 +11,4 @@ util-obj-y += iov.o aes.o qemu-config.o qemu-sockets.o uri.o notify.o
 util-obj-y += qemu-option.o qemu-progress.o
 util-obj-y += hexdump.o
 util-obj-y += crc32c.o
+util-obj-y += qemu-time.o
diff --git a/util/qemu-error.c b/util/qemu-error.c
index 08a36f4..33fa9d3 100644
--- a/util/qemu-error.c
+++ b/util/qemu-error.c
@@ -12,6 +12,7 @@
 
 #include <stdio.h>
 #include "monitor/monitor.h"
+#include "qemu/time.h"
 
 /*
  * Print to current monitor if we have one, else to stderr.
@@ -196,6 +197,7 @@ void error_print_loc(void)
     }
 }
 
+bool enable_timestamp_msg;
 /*
  * Print an error message to current monitor if we have one, else to stderr.
  * Format arguments like sprintf().  The result should not contain
@@ -206,6 +208,12 @@ void error_print_loc(void)
 void error_report(const char *fmt, ...)
 {
     va_list ap;
+    char timestr[TIMESTAMP_LEN];
+
+    if (enable_timestamp_msg) {
+        qemu_get_timestamp_str(&timestr);
+        error_printf("%s ", timestr);
+    }
 
     error_print_loc();
     va_start(ap, fmt);
diff --git a/util/qemu-time.c b/util/qemu-time.c
new file mode 100644
index 0000000..37f7b9e
--- /dev/null
+++ b/util/qemu-time.c
@@ -0,0 +1,24 @@
+/*
+ * Time handling
+ *
+ * Copyright (C) 2013 Hitachi Data Systems Corp.
+ *
+ * Authors:
+ *  Seiji Aguchi <sei...@hd...>
+ *
+ * This work is licensed under the terms of the GNU GPL, version 2 or later.
+ * See the COPYING file in the top-level directory.
+ */
+#include "qemu/time.h"
+
+void qemu_get_timestamp_str(char (*timestr)[])
+{
+    GTimeVal tv;
+    gchar *tmp_str = NULL;
+
+    g_get_current_time(&tv);
+    tmp_str = g_time_val_to_iso8601(&tv);
+    g_strlcpy((gchar *)*timestr, tmp_str, TIMESTAMP_LEN);
+    g_free(tmp_str);
+    return;
+}
diff --git a/vl.c b/vl.c
index 0a8f056..aee7350 100644
--- a/vl.c
+++ b/vl.c
@@ -171,6 +171,8 @@ int main(int argc, char **argv)
 #include "ui/qemu-spice.h"
 #include "qapi/string-input-visitor.h"
 
+#include "qemu/time.h"
+
 //#define DEBUG_NET
 //#define DEBUG_SLIRP
 
@@ -516,6 +518,18 @@ static QemuOptsList qemu_realtime_opts = {
     },
 };
 
+static QemuOptsList qemu_msg_opts = {
+    .name = "msg",
+    .head = QTAILQ_HEAD_INITIALIZER(qemu_msg_opts.head),
+    .desc = {
+        {
+            .name = "timestamp",
+            .type = QEMU_OPT_BOOL,
+        },
+        { /* end of list */ }
+    },
+};
+
 const char *qemu_get_vm_name(void)
 {
     return qemu_name;
@@ -1459,6 +1473,12 @@ static void configure_realtime(QemuOpts *opts)
     }
 }
 
+
+static void configure_msg(QemuOpts *opts)
+{
+    enable_timestamp_msg = qemu_opt_get_bool(opts, "timestamp", true);
+}
+
 /***********************************************************/
 /* USB devices */
 
@@ -2901,6 +2921,7 @@ int main(int argc, char **argv, char **envp)
     qemu_add_opts(&qemu_object_opts);
     qemu_add_opts(&qemu_tpmdev_opts);
     qemu_add_opts(&qemu_realtime_opts);
+    qemu_add_opts(&qemu_msg_opts);
 
     runstate_init();
 
@@ -3808,6 +3829,13 @@ int main(int argc, char **argv, char **envp)
                 }
                 configure_realtime(opts);
                 break;
+            case QEMU_OPTION_msg:
+                opts = qemu_opts_parse(qemu_find_opts("msg"), optarg, 0);
+                if (!opts) {
+                    exit(1);
+                }
+                configure_msg(opts);
+                break;
             default:
                 os_parse_cmd_args(popt->index, optarg);
             }
-- 
1.7.1

Re: [Dle-develop] [Qemu-devel] [PATCH v3] Add timestamp to error message

[Seiji A. <sei...@hd...>]

> Signed-off-by: Seiji Aguchi <sa...@re...>

I used wrong email address to Signed-off-by.
Please ignore this patch.

Seiji

> -----Original Message-----
> From: qem...@no... [mailto:qem...@no...]
> On Behalf Of Seiji Aguchi
> Sent: Wednesday, June 26, 2013 6:21 PM
> To: qem...@no...
> Cc: kw...@re...; ali...@us...; Tomoki Sekiyama; ms...@re...; ste...@gm...; mto...@re...;
> ar...@re...; lca...@re...; dle...@li...; av...@co...; ste...@re...;
> pbo...@re...
> Subject: [Qemu-devel] [PATCH v3] Add timestamp to error message
> 
> [Issue]
> When we offer a customer support service and a problem happens
> in a customer's system, we try to understand the problem by
> comparing what the customer reports with message logs of the
> customer's system.
> 
> In this case, we often need to know when the problem happens.
> 
> But, currently, there is no timestamp in qemu's error messages.
> Therefore, we may not be able to understand the problem based on
> error messages.
> 
> [Solution]
> Add a timestamp to qemu's error message logged by
> error_report() with g_time_val_to_iso8601().
> 
> [TODO]
> Add timestamp to monitor_printf() and fprintf().
> 
> Signed-off-by: Seiji Aguchi <sa...@re...>
> ---
> Changelog
>  v2 -> v3
> 
>  - Use g_time_val_to_iso8601() to get timestamp instead of
>    copying libvirt's time-handling functions.
> 
>    According to discussion below, qemu doesn't need to take care
>    if timestamp functions are async-signal safe or not.
> 
>    http://marc.info/?l=qemu-devel&m=136741841921265&w=2
> 
>    Also, In the review of v2 patch, strftime() are recommended to
>    format string. But it is not a suitable function to handle msec.
> 
>    Then, simply call g_time_val_to_iso8601().
> 
>  - Intoroduce a common time-handling function to util/qemu-time.c.
>    (Suggested by Daniel P. Berrange)
> 
>  v1 -> v2
> 
>  - add an option, -msg timestamp={on|off}, to enable output message with timestamp
> ---
>  include/qemu/time.h |   11 +++++++++++
>  qemu-options.hx     |   12 ++++++++++++
>  util/Makefile.objs  |    1 +
>  util/qemu-error.c   |    8 ++++++++
>  util/qemu-time.c    |   24 ++++++++++++++++++++++++
>  vl.c                |   28 ++++++++++++++++++++++++++++
>  6 files changed, 84 insertions(+), 0 deletions(-)
>  create mode 100644 include/qemu/time.h
>  create mode 100644 util/qemu-time.c
> 
> diff --git a/include/qemu/time.h b/include/qemu/time.h
> new file mode 100644
> index 0000000..f70739b
> --- /dev/null
> +++ b/include/qemu/time.h
> @@ -0,0 +1,11 @@
> +#ifndef TIME_H
> +#define TIME_H
> +
> +#include "qemu-common.h"
> +
> +/*  "1970-01-01T00:00:00.999999Z" + '\0' */
> +#define TIMESTAMP_LEN 28
> +extern void qemu_get_timestamp_str(char (*timestr)[]);
> +extern bool enable_timestamp_msg;
> +
> +#endif /* !TIME_H */
> diff --git a/qemu-options.hx b/qemu-options.hx
> index ca6fdf6..7890921 100644
> --- a/qemu-options.hx
> +++ b/qemu-options.hx
> @@ -3102,3 +3102,15 @@ HXCOMM This is the last statement. Insert new options before this line!
>  STEXI
>  @end table
>  ETEXI
> +
> +DEF("msg", HAS_ARG, QEMU_OPTION_msg,
> +    "-msg [timestamp=on|off]\n"
> +    "                output message with timestamp (default: off)\n",
> +    QEMU_ARCH_ALL)
> +STEXI
> +@item -msg timestamp=on|off
> +@findex - msg
> +Output message with timestamp.
> +Adding timestamp to messages with @option{timestamp=on}
> +(disabled by default).
> +ETEXI
> diff --git a/util/Makefile.objs b/util/Makefile.objs
> index dc72ab0..063db56 100644
> --- a/util/Makefile.objs
> +++ b/util/Makefile.objs
> @@ -11,3 +11,4 @@ util-obj-y += iov.o aes.o qemu-config.o qemu-sockets.o uri.o notify.o
>  util-obj-y += qemu-option.o qemu-progress.o
>  util-obj-y += hexdump.o
>  util-obj-y += crc32c.o
> +util-obj-y += qemu-time.o
> diff --git a/util/qemu-error.c b/util/qemu-error.c
> index 08a36f4..33fa9d3 100644
> --- a/util/qemu-error.c
> +++ b/util/qemu-error.c
> @@ -12,6 +12,7 @@
> 
>  #include <stdio.h>
>  #include "monitor/monitor.h"
> +#include "qemu/time.h"
> 
>  /*
>   * Print to current monitor if we have one, else to stderr.
> @@ -196,6 +197,7 @@ void error_print_loc(void)
>      }
>  }
> 
> +bool enable_timestamp_msg;
>  /*
>   * Print an error message to current monitor if we have one, else to stderr.
>   * Format arguments like sprintf().  The result should not contain
> @@ -206,6 +208,12 @@ void error_print_loc(void)
>  void error_report(const char *fmt, ...)
>  {
>      va_list ap;
> +    char timestr[TIMESTAMP_LEN];
> +
> +    if (enable_timestamp_msg) {
> +        qemu_get_timestamp_str(&timestr);
> +        error_printf("%s ", timestr);
> +    }
> 
>      error_print_loc();
>      va_start(ap, fmt);
> diff --git a/util/qemu-time.c b/util/qemu-time.c
> new file mode 100644
> index 0000000..37f7b9e
> --- /dev/null
> +++ b/util/qemu-time.c
> @@ -0,0 +1,24 @@
> +/*
> + * Time handling
> + *
> + * Copyright (C) 2013 Hitachi Data Systems Corp.
> + *
> + * Authors:
> + *  Seiji Aguchi <sei...@hd...>
> + *
> + * This work is licensed under the terms of the GNU GPL, version 2 or later.
> + * See the COPYING file in the top-level directory.
> + */
> +#include "qemu/time.h"
> +
> +void qemu_get_timestamp_str(char (*timestr)[])
> +{
> +    GTimeVal tv;
> +    gchar *tmp_str = NULL;
> +
> +    g_get_current_time(&tv);
> +    tmp_str = g_time_val_to_iso8601(&tv);
> +    g_strlcpy((gchar *)*timestr, tmp_str, TIMESTAMP_LEN);
> +    g_free(tmp_str);
> +    return;
> +}
> diff --git a/vl.c b/vl.c
> index 0a8f056..aee7350 100644
> --- a/vl.c
> +++ b/vl.c
> @@ -171,6 +171,8 @@ int main(int argc, char **argv)
>  #include "ui/qemu-spice.h"
>  #include "qapi/string-input-visitor.h"
> 
> +#include "qemu/time.h"
> +
>  //#define DEBUG_NET
>  //#define DEBUG_SLIRP
> 
> @@ -516,6 +518,18 @@ static QemuOptsList qemu_realtime_opts = {
>      },
>  };
> 
> +static QemuOptsList qemu_msg_opts = {
> +    .name = "msg",
> +    .head = QTAILQ_HEAD_INITIALIZER(qemu_msg_opts.head),
> +    .desc = {
> +        {
> +            .name = "timestamp",
> +            .type = QEMU_OPT_BOOL,
> +        },
> +        { /* end of list */ }
> +    },
> +};
> +
>  const char *qemu_get_vm_name(void)
>  {
>      return qemu_name;
> @@ -1459,6 +1473,12 @@ static void configure_realtime(QemuOpts *opts)
>      }
>  }
> 
> +
> +static void configure_msg(QemuOpts *opts)
> +{
> +    enable_timestamp_msg = qemu_opt_get_bool(opts, "timestamp", true);
> +}
> +
>  /***********************************************************/
>  /* USB devices */
> 
> @@ -2901,6 +2921,7 @@ int main(int argc, char **argv, char **envp)
>      qemu_add_opts(&qemu_object_opts);
>      qemu_add_opts(&qemu_tpmdev_opts);
>      qemu_add_opts(&qemu_realtime_opts);
> +    qemu_add_opts(&qemu_msg_opts);
> 
>      runstate_init();
> 
> @@ -3808,6 +3829,13 @@ int main(int argc, char **argv, char **envp)
>                  }
>                  configure_realtime(opts);
>                  break;
> +            case QEMU_OPTION_msg:
> +                opts = qemu_opts_parse(qemu_find_opts("msg"), optarg, 0);
> +                if (!opts) {
> +                    exit(1);
> +                }
> +                configure_msg(opts);
> +                break;
>              default:
>                  os_parse_cmd_args(popt->index, optarg);
>              }
> --
> 1.7.1
> 

[Dle-develop] [PATCH v3] Add timestamp to error message

[Seiji A. <sei...@hd...>]

[Issue]
When we offer a customer support service and a problem happens
in a customer's system, we try to understand the problem by
comparing what the customer reports with message logs of the
customer's system.

In this case, we often need to know when the problem happens.

But, currently, there is no timestamp in qemu's error messages.
Therefore, we may not be able to understand the problem based on
error messages.

[Solution]
Add a timestamp to qemu's error message logged by
error_report() with g_time_val_to_iso8601().

[TODO]
Add timestamp to monitor_printf() and fprintf().

Signed-off-by: Seiji Aguchi <sa...@re...>
---
Changelog
 v2 -> v3

 - Use g_time_val_to_iso8601() to get timestamp instead of
   copying libvirt's time-handling functions.

   According to discussion below, qemu doesn't need to take care
   if timestamp functions are async-signal safe or not.

   http://marc.info/?l=qemu-devel&m=136741841921265&w=2

   Also, In the review of v2 patch, strftime() are recommended to
   format string. But it is not a suitable function to handle msec.

   Then, simply call g_time_val_to_iso8601().

 - Intoroduce a common time-handling function to util/qemu-time.c.
   (Suggested by Daniel P. Berrange)

 v1 -> v2

 - add an option, -msg timestamp={on|off}, to enable output message with timestamp
---
 include/qemu/time.h |   11 +++++++++++
 qemu-options.hx     |   12 ++++++++++++
 util/Makefile.objs  |    1 +
 util/qemu-error.c   |    8 ++++++++
 util/qemu-time.c    |   24 ++++++++++++++++++++++++
 vl.c                |   28 ++++++++++++++++++++++++++++
 6 files changed, 84 insertions(+), 0 deletions(-)
 create mode 100644 include/qemu/time.h
 create mode 100644 util/qemu-time.c

diff --git a/include/qemu/time.h b/include/qemu/time.h
new file mode 100644
index 0000000..f70739b
--- /dev/null
+++ b/include/qemu/time.h
@@ -0,0 +1,11 @@
+#ifndef TIME_H
+#define TIME_H
+
+#include "qemu-common.h"
+
+/*  "1970-01-01T00:00:00.999999Z" + '\0' */
+#define TIMESTAMP_LEN 28
+extern void qemu_get_timestamp_str(char (*timestr)[]);
+extern bool enable_timestamp_msg;
+
+#endif /* !TIME_H */
diff --git a/qemu-options.hx b/qemu-options.hx
index ca6fdf6..7890921 100644
--- a/qemu-options.hx
+++ b/qemu-options.hx
@@ -3102,3 +3102,15 @@ HXCOMM This is the last statement. Insert new options before this line!
 STEXI
 @end table
 ETEXI
+
+DEF("msg", HAS_ARG, QEMU_OPTION_msg,
+    "-msg [timestamp=on|off]\n"
+    "                output message with timestamp (default: off)\n",
+    QEMU_ARCH_ALL)
+STEXI
+@item -msg timestamp=on|off
+@findex - msg
+Output message with timestamp.
+Adding timestamp to messages with @option{timestamp=on}
+(disabled by default).
+ETEXI
diff --git a/util/Makefile.objs b/util/Makefile.objs
index dc72ab0..063db56 100644
--- a/util/Makefile.objs
+++ b/util/Makefile.objs
@@ -11,3 +11,4 @@ util-obj-y += iov.o aes.o qemu-config.o qemu-sockets.o uri.o notify.o
 util-obj-y += qemu-option.o qemu-progress.o
 util-obj-y += hexdump.o
 util-obj-y += crc32c.o
+util-obj-y += qemu-time.o
diff --git a/util/qemu-error.c b/util/qemu-error.c
index 08a36f4..33fa9d3 100644
--- a/util/qemu-error.c
+++ b/util/qemu-error.c
@@ -12,6 +12,7 @@
 
 #include <stdio.h>
 #include "monitor/monitor.h"
+#include "qemu/time.h"
 
 /*
  * Print to current monitor if we have one, else to stderr.
@@ -196,6 +197,7 @@ void error_print_loc(void)
     }
 }
 
+bool enable_timestamp_msg;
 /*
  * Print an error message to current monitor if we have one, else to stderr.
  * Format arguments like sprintf().  The result should not contain
@@ -206,6 +208,12 @@ void error_print_loc(void)
 void error_report(const char *fmt, ...)
 {
     va_list ap;
+    char timestr[TIMESTAMP_LEN];
+
+    if (enable_timestamp_msg) {
+        qemu_get_timestamp_str(&timestr);
+        error_printf("%s ", timestr);
+    }
 
     error_print_loc();
     va_start(ap, fmt);
diff --git a/util/qemu-time.c b/util/qemu-time.c
new file mode 100644
index 0000000..37f7b9e
--- /dev/null
+++ b/util/qemu-time.c
@@ -0,0 +1,24 @@
+/*
+ * Time handling
+ *
+ * Copyright (C) 2013 Hitachi Data Systems Corp.
+ *
+ * Authors:
+ *  Seiji Aguchi <sei...@hd...>
+ *
+ * This work is licensed under the terms of the GNU GPL, version 2 or later.
+ * See the COPYING file in the top-level directory.
+ */
+#include "qemu/time.h"
+
+void qemu_get_timestamp_str(char (*timestr)[])
+{
+    GTimeVal tv;
+    gchar *tmp_str = NULL;
+
+    g_get_current_time(&tv);
+    tmp_str = g_time_val_to_iso8601(&tv);
+    g_strlcpy((gchar *)*timestr, tmp_str, TIMESTAMP_LEN);
+    g_free(tmp_str);
+    return;
+}
diff --git a/vl.c b/vl.c
index 0a8f056..aee7350 100644
--- a/vl.c
+++ b/vl.c
@@ -171,6 +171,8 @@ int main(int argc, char **argv)
 #include "ui/qemu-spice.h"
 #include "qapi/string-input-visitor.h"
 
+#include "qemu/time.h"
+
 //#define DEBUG_NET
 //#define DEBUG_SLIRP
 
@@ -516,6 +518,18 @@ static QemuOptsList qemu_realtime_opts = {
     },
 };
 
+static QemuOptsList qemu_msg_opts = {
+    .name = "msg",
+    .head = QTAILQ_HEAD_INITIALIZER(qemu_msg_opts.head),
+    .desc = {
+        {
+            .name = "timestamp",
+            .type = QEMU_OPT_BOOL,
+        },
+        { /* end of list */ }
+    },
+};
+
 const char *qemu_get_vm_name(void)
 {
     return qemu_name;
@@ -1459,6 +1473,12 @@ static void configure_realtime(QemuOpts *opts)
     }
 }
 
+
+static void configure_msg(QemuOpts *opts)
+{
+    enable_timestamp_msg = qemu_opt_get_bool(opts, "timestamp", true);
+}
+
 /***********************************************************/
 /* USB devices */
 
@@ -2901,6 +2921,7 @@ int main(int argc, char **argv, char **envp)
     qemu_add_opts(&qemu_object_opts);
     qemu_add_opts(&qemu_tpmdev_opts);
     qemu_add_opts(&qemu_realtime_opts);
+    qemu_add_opts(&qemu_msg_opts);
 
     runstate_init();
 
@@ -3808,6 +3829,13 @@ int main(int argc, char **argv, char **envp)
                 }
                 configure_realtime(opts);
                 break;
+            case QEMU_OPTION_msg:
+                opts = qemu_opts_parse(qemu_find_opts("msg"), optarg, 0);
+                if (!opts) {
+                    exit(1);
+                }
+                configure_msg(opts);
+                break;
             default:
                 os_parse_cmd_args(popt->index, optarg);
             }
-- 
1.7.1

[Dle-develop] [PATCH v17 4/4] trace, x86: Add irq vector tracepoints

[Seiji A. <sei...@hd...>]

[Purpose of this patch]

As Vaibhav explained in the thread below, tracepoints for irq vectors
are useful.

http://www.spinics.net/lists/mm-commits/msg85707.html

<snip>
The current interrupt traces from irq_handler_entry and irq_handler_exit
provide when an interrupt is handled.  They provide good data about when
the system has switched to kernel space and how it affects the currently
running processes.

There are some IRQ vectors which trigger the system into kernel space,
which are not handled in generic IRQ handlers.  Tracing such events gives
us the information about IRQ interaction with other system events.

The trace also tells where the system is spending its time.  We want to
know which cores are handling interrupts and how they are affecting other
processes in the system.  Also, the trace provides information about when
the cores are idle and which interrupts are changing that state.
<snip>

On the other hand, my usecase is tracing just local timer event and
getting a value of instruction pointer.

I suggested to add an argument local timer event to get instruction pointer before.
But there is another way to get it with external module like systemtap.
So, I don't need to add any argument to irq vector tracepoints now.

[Patch Description]

Vaibhav's patch shared a trace point ,irq_vector_entry/irq_vector_exit, in all events.
But there is an above use case to trace specific irq_vector rather than tracing all events.
In this case, we are concerned about overhead due to unwanted events.

So, add following tracepoints instead of introducing irq_vector_entry/exit.
so that we can enable them independently.
   - local_timer_vector
   - reschedule_vector
   - call_function_vector
   - call_function_single_vector
   - irq_work_entry_vector
   - error_apic_vector
   - thermal_apic_vector
   - threshold_apic_vector
   - spurious_apic_vector
   - x86_platform_ipi_vector

Also, introduce a logic switching IDT at enabling/disabling time so that a time penalty
makes a zero when tracepoints are disabled. Detailed explanations are as follows.
 - Create trace irq handlers with entering_irq()/exiting_irq().
 - Create a new IDT, trace_idt_table, at boot time by adding a logic to
   _set_gate(). It is just a copy of original idt table.
 - Register the new handlers for tracpoints to the new IDT by introducing
   macros to alloc_intr_gate() called at registering time of irq_vector handlers.
 - Add checking, whether irq vector tracing is on/off, into load_current_idt().
   This has to be done below debug checking for these reasons.
   - Switching to debug IDT may be kicked while tracing is enabled.
   - On the other hands, switching to trace IDT is kicked only when debugging
     is disabled.

In addition, the new IDT is created only when CONFIG_TRACING is enabled to avoid being
used for other purposes.

Signed-off-by: Seiji Aguchi <sei...@hd...>
---
 arch/x86/include/asm/desc.h              |   72 ++++++++++++++++++++-
 arch/x86/include/asm/entry_arch.h        |    8 ++-
 arch/x86/include/asm/hw_irq.h            |   17 +++++
 arch/x86/include/asm/mshyperv.h          |    3 +
 arch/x86/include/asm/trace/irq_vectors.h |  104 ++++++++++++++++++++++++++++++
 arch/x86/include/asm/uv/uv_bau.h         |    3 +
 arch/x86/kernel/Makefile                 |    1 +
 arch/x86/kernel/apic/Makefile            |    1 +
 arch/x86/kernel/apic/apic.c              |   42 ++++++++++++
 arch/x86/kernel/cpu/common.c             |    4 +-
 arch/x86/kernel/cpu/mcheck/therm_throt.c |   10 +++
 arch/x86/kernel/cpu/mcheck/threshold.c   |    9 +++
 arch/x86/kernel/entry_32.S               |   12 +++-
 arch/x86/kernel/entry_64.S               |   31 +++++++--
 arch/x86/kernel/head_64.S                |    6 ++
 arch/x86/kernel/irq.c                    |   13 ++++
 arch/x86/kernel/irq_work.c               |   10 +++
 arch/x86/kernel/smp.c                    |   30 +++++++++
 arch/x86/kernel/tracepoint.c             |   57 ++++++++++++++++
 include/xen/events.h                     |    3 +
 20 files changed, 421 insertions(+), 15 deletions(-)
 create mode 100644 arch/x86/include/asm/trace/irq_vectors.h
 create mode 100644 arch/x86/kernel/tracepoint.c

diff --git a/arch/x86/include/asm/desc.h b/arch/x86/include/asm/desc.h
index af290b8..1377ecb 100644
--- a/arch/x86/include/asm/desc.h
+++ b/arch/x86/include/asm/desc.h
@@ -320,6 +320,19 @@ static inline void set_nmi_gate(int gate, void *addr)
 }
 #endif
 
+#ifdef CONFIG_TRACING
+extern struct desc_ptr trace_idt_descr;
+extern gate_desc trace_idt_table[];
+static inline void write_trace_idt_entry(int entry, const gate_desc *gate)
+{
+	write_idt_entry(trace_idt_table, entry, gate);
+}
+#else
+static inline void write_trace_idt_entry(int entry, const gate_desc *gate)
+{
+}
+#endif
+
 static inline void _set_gate(int gate, unsigned type, void *addr,
 			     unsigned dpl, unsigned ist, unsigned seg)
 {
@@ -331,6 +344,7 @@ static inline void _set_gate(int gate, unsigned type, void *addr,
 	 * setup time
 	 */
 	write_idt_entry(idt_table, gate, &s);
+	write_trace_idt_entry(gate, &s);
 }
 
 /*
@@ -360,12 +374,39 @@ static inline void alloc_system_vector(int vector)
 	}
 }
 
-static inline void alloc_intr_gate(unsigned int n, void *addr)
+#ifdef CONFIG_TRACING
+static inline void trace_set_intr_gate(unsigned int gate, void *addr)
+{
+	gate_desc s;
+
+	pack_gate(&s, GATE_INTERRUPT, (unsigned long)addr, 0, 0, __KERNEL_CS);
+	write_idt_entry(trace_idt_table, gate, &s);
+}
+
+static inline void __trace_alloc_intr_gate(unsigned int n, void *addr)
+{
+	trace_set_intr_gate(n, addr);
+}
+#else
+static inline void trace_set_intr_gate(unsigned int gate, void *addr)
+{
+}
+
+#define __trace_alloc_intr_gate(n, addr)
+#endif
+
+static inline void __alloc_intr_gate(unsigned int n, void *addr)
 {
-	alloc_system_vector(n);
 	set_intr_gate(n, addr);
 }
 
+#define alloc_intr_gate(n, addr)				\
+	do {							\
+		alloc_system_vector(n);				\
+		__alloc_intr_gate(n, addr);			\
+		__trace_alloc_intr_gate(n, trace_##addr);	\
+	} while (0)
+
 /*
  * This routine sets up an interrupt gate at directory privilege level 3.
  */
@@ -430,6 +471,31 @@ static inline void load_debug_idt(void)
 }
 #endif
 
+#ifdef CONFIG_TRACING
+extern atomic_t trace_idt_ctr;
+static inline bool is_trace_idt_enabled(void)
+{
+	if (atomic_read(&trace_idt_ctr))
+		return true;
+
+	return false;
+}
+
+static inline void load_trace_idt(void)
+{
+	load_idt((const struct desc_ptr *)&trace_idt_descr);
+}
+#else
+static inline bool is_trace_idt_enabled(void)
+{
+	return false;
+}
+
+static inline void load_trace_idt(void)
+{
+}
+#endif
+
 /*
  * the load_current_idt() is called with interrupt disabled by local_irq_save()
  * to avoid races. That way the IDT will always be set back to the expected
@@ -442,6 +508,8 @@ static inline void load_current_idt(void)
 	local_irq_save(flags);
 	if (is_debug_idt_enabled())
 		load_debug_idt();
+	else if (is_trace_idt_enabled())
+		load_trace_idt();
 	else
 		load_idt((const struct desc_ptr *)&idt_descr);
 	local_irq_restore(flags);
diff --git a/arch/x86/include/asm/entry_arch.h b/arch/x86/include/asm/entry_arch.h
index 9bd4eca..dc5fa66 100644
--- a/arch/x86/include/asm/entry_arch.h
+++ b/arch/x86/include/asm/entry_arch.h
@@ -13,14 +13,16 @@
 BUILD_INTERRUPT(reschedule_interrupt,RESCHEDULE_VECTOR)
 BUILD_INTERRUPT(call_function_interrupt,CALL_FUNCTION_VECTOR)
 BUILD_INTERRUPT(call_function_single_interrupt,CALL_FUNCTION_SINGLE_VECTOR)
-BUILD_INTERRUPT(irq_move_cleanup_interrupt,IRQ_MOVE_CLEANUP_VECTOR)
-BUILD_INTERRUPT(reboot_interrupt,REBOOT_VECTOR)
+BUILD_INTERRUPT3(irq_move_cleanup_interrupt, IRQ_MOVE_CLEANUP_VECTOR,
+		 smp_irq_move_cleanup_interrupt)
+BUILD_INTERRUPT3(reboot_interrupt, REBOOT_VECTOR, smp_reboot_interrupt)
 #endif
 
 BUILD_INTERRUPT(x86_platform_ipi, X86_PLATFORM_IPI_VECTOR)
 
 #ifdef CONFIG_HAVE_KVM
-BUILD_INTERRUPT(kvm_posted_intr_ipi, POSTED_INTR_VECTOR)
+BUILD_INTERRUPT3(kvm_posted_intr_ipi, POSTED_INTR_VECTOR,
+		 smp_kvm_posted_intr_ipi)
 #endif
 
 /*
diff --git a/arch/x86/include/asm/hw_irq.h b/arch/x86/include/asm/hw_irq.h
index 1da97ef..e4ac559 100644
--- a/arch/x86/include/asm/hw_irq.h
+++ b/arch/x86/include/asm/hw_irq.h
@@ -77,6 +77,23 @@ extern void threshold_interrupt(void);
 extern void call_function_interrupt(void);
 extern void call_function_single_interrupt(void);
 
+#ifdef CONFIG_TRACING
+/* Interrupt handlers registered during init_IRQ */
+extern void trace_apic_timer_interrupt(void);
+extern void trace_x86_platform_ipi(void);
+extern void trace_error_interrupt(void);
+extern void trace_irq_work_interrupt(void);
+extern void trace_spurious_interrupt(void);
+extern void trace_thermal_interrupt(void);
+extern void trace_reschedule_interrupt(void);
+extern void trace_threshold_interrupt(void);
+extern void trace_call_function_interrupt(void);
+extern void trace_call_function_single_interrupt(void);
+#define trace_irq_move_cleanup_interrupt  irq_move_cleanup_interrupt
+#define trace_reboot_interrupt  reboot_interrupt
+#define trace_kvm_posted_intr_ipi kvm_posted_intr_ipi
+#endif /* CONFIG_TRACING */
+
 /* IOAPIC */
 #define IO_APIC_IRQ(x) (((x) >= NR_IRQS_LEGACY) || ((1<<(x)) & io_apic_irqs))
 extern unsigned long io_apic_irqs;
diff --git a/arch/x86/include/asm/mshyperv.h b/arch/x86/include/asm/mshyperv.h
index c2934be..cd9c419 100644
--- a/arch/x86/include/asm/mshyperv.h
+++ b/arch/x86/include/asm/mshyperv.h
@@ -12,6 +12,9 @@ struct ms_hyperv_info {
 extern struct ms_hyperv_info ms_hyperv;
 
 void hyperv_callback_vector(void);
+#ifdef CONFIG_TRACING
+#define trace_hyperv_callback_vector hyperv_callback_vector
+#endif
 void hyperv_vector_handler(struct pt_regs *regs);
 void hv_register_vmbus_handler(int irq, irq_handler_t handler);
 
diff --git a/arch/x86/include/asm/trace/irq_vectors.h b/arch/x86/include/asm/trace/irq_vectors.h
new file mode 100644
index 0000000..2874df2
--- /dev/null
+++ b/arch/x86/include/asm/trace/irq_vectors.h
@@ -0,0 +1,104 @@
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM irq_vectors
+
+#if !defined(_TRACE_IRQ_VECTORS_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_IRQ_VECTORS_H
+
+#include <linux/tracepoint.h>
+
+extern void trace_irq_vector_regfunc(void);
+extern void trace_irq_vector_unregfunc(void);
+
+DECLARE_EVENT_CLASS(x86_irq_vector,
+
+	TP_PROTO(int vector),
+
+	TP_ARGS(vector),
+
+	TP_STRUCT__entry(
+		__field(		int,	vector	)
+	),
+
+	TP_fast_assign(
+		__entry->vector = vector;
+	),
+
+	TP_printk("vector=%d", __entry->vector) );
+
+#define DEFINE_IRQ_VECTOR_EVENT(name)		\
+DEFINE_EVENT_FN(x86_irq_vector, name##_entry,	\
+	TP_PROTO(int vector),			\
+	TP_ARGS(vector),			\
+	trace_irq_vector_regfunc,		\
+	trace_irq_vector_unregfunc);		\
+DEFINE_EVENT_FN(x86_irq_vector, name##_exit,	\
+	TP_PROTO(int vector),			\
+	TP_ARGS(vector),			\
+	trace_irq_vector_regfunc,		\
+	trace_irq_vector_unregfunc);
+
+
+/*
+ * local_timer - called when entering/exiting a local timer interrupt
+ * vector handler
+ */
+DEFINE_IRQ_VECTOR_EVENT(local_timer);
+
+/*
+ * reschedule - called when entering/exiting a reschedule vector handler
+ */
+DEFINE_IRQ_VECTOR_EVENT(reschedule);
+
+/*
+ * spurious_apic - called when entering/exiting a spurious apic vector handler
+ */
+DEFINE_IRQ_VECTOR_EVENT(spurious_apic);
+
+/*
+ * error_apic - called when entering/exiting an error apic vector handler
+ */
+DEFINE_IRQ_VECTOR_EVENT(error_apic);
+
+/*
+ * x86_platform_ipi - called when entering/exiting a x86 platform ipi interrupt
+ * vector handler
+ */
+DEFINE_IRQ_VECTOR_EVENT(x86_platform_ipi);
+
+/*
+ * irq_work - called when entering/exiting a irq work interrupt
+ * vector handler
+ */
+DEFINE_IRQ_VECTOR_EVENT(irq_work);
+
+/*
+ * call_function - called when entering/exiting a call function interrupt
+ * vector handler
+ */
+DEFINE_IRQ_VECTOR_EVENT(call_function);
+
+/*
+ * call_function_single - called when entering/exiting a call function
+ * single interrupt vector handler
+ */
+DEFINE_IRQ_VECTOR_EVENT(call_function_single);
+
+/*
+ * threshold_apic - called when entering/exiting a threshold apic interrupt
+ * vector handler
+ */
+DEFINE_IRQ_VECTOR_EVENT(threshold_apic);
+
+/*
+ * thermal_apic - called when entering/exiting a thermal apic interrupt
+ * vector handler
+ */
+DEFINE_IRQ_VECTOR_EVENT(thermal_apic);
+
+#undef TRACE_INCLUDE_PATH
+#define TRACE_INCLUDE_PATH .
+#define TRACE_INCLUDE_FILE irq_vectors
+#endif /*  _TRACE_IRQ_VECTORS_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>
diff --git a/arch/x86/include/asm/uv/uv_bau.h b/arch/x86/include/asm/uv/uv_bau.h
index a06983c..0b46ef2 100644
--- a/arch/x86/include/asm/uv/uv_bau.h
+++ b/arch/x86/include/asm/uv/uv_bau.h
@@ -731,6 +731,9 @@ static inline void bau_cpubits_clear(struct bau_local_cpumask *dstp, int nbits)
 }
 
 extern void uv_bau_message_intr1(void);
+#ifdef CONFIG_TRACING
+#define trace_uv_bau_message_intr1 uv_bau_message_intr1
+#endif
 extern void uv_bau_timeout_intr1(void);
 
 struct atomic_short {
diff --git a/arch/x86/kernel/Makefile b/arch/x86/kernel/Makefile
index 7bd3bd3..74b3891 100644
--- a/arch/x86/kernel/Makefile
+++ b/arch/x86/kernel/Makefile
@@ -102,6 +102,7 @@ obj-$(CONFIG_OF)			+= devicetree.o
 obj-$(CONFIG_UPROBES)			+= uprobes.o
 
 obj-$(CONFIG_PERF_EVENTS)		+= perf_regs.o
+obj-$(CONFIG_TRACING)			+= tracepoint.o
 
 ###
 # 64 bit specific files
diff --git a/arch/x86/kernel/apic/Makefile b/arch/x86/kernel/apic/Makefile
index 0ae0323..5274c3a 100644
--- a/arch/x86/kernel/apic/Makefile
+++ b/arch/x86/kernel/apic/Makefile
@@ -2,6 +2,7 @@
 # Makefile for local APIC drivers and for the IO-APIC code
 #
 
+CFLAGS_apic.o := -I$(src)/../../include/asm/trace
 obj-$(CONFIG_X86_LOCAL_APIC)	+= apic.o apic_noop.o ipi.o
 obj-y				+= hw_nmi.o
 
diff --git a/arch/x86/kernel/apic/apic.c b/arch/x86/kernel/apic/apic.c
index 59ee76f..61ced40 100644
--- a/arch/x86/kernel/apic/apic.c
+++ b/arch/x86/kernel/apic/apic.c
@@ -55,6 +55,9 @@
 #include <asm/tsc.h>
 #include <asm/hypervisor.h>
 
+#define CREATE_TRACE_POINTS
+#include <asm/trace/irq_vectors.h>
+
 unsigned int num_processors;
 
 unsigned disabled_cpus __cpuinitdata;
@@ -931,6 +934,27 @@ void __irq_entry smp_apic_timer_interrupt(struct pt_regs *regs)
 	set_irq_regs(old_regs);
 }
 
+void __irq_entry smp_trace_apic_timer_interrupt(struct pt_regs *regs)
+{
+	struct pt_regs *old_regs = set_irq_regs(regs);
+
+	/*
+	 * NOTE! We'd better ACK the irq immediately,
+	 * because timer handling can be slow.
+	 *
+	 * update_process_times() expects us to have done irq_enter().
+	 * Besides, if we don't timer interrupts ignore the global
+	 * interrupt lock, which is the WrongThing (tm) to do.
+	 */
+	entering_ack_irq();
+	trace_local_timer_entry(LOCAL_TIMER_VECTOR);
+	local_apic_timer_interrupt();
+	trace_local_timer_exit(LOCAL_TIMER_VECTOR);
+	exiting_irq();
+
+	set_irq_regs(old_regs);
+}
+
 int setup_profiling_timer(unsigned int multiplier)
 {
 	return -EINVAL;
@@ -1931,6 +1955,15 @@ void smp_spurious_interrupt(struct pt_regs *regs)
 	exiting_irq();
 }
 
+void smp_trace_spurious_interrupt(struct pt_regs *regs)
+{
+	entering_irq();
+	trace_spurious_apic_entry(SPURIOUS_APIC_VECTOR);
+	__smp_spurious_interrupt();
+	trace_spurious_apic_exit(SPURIOUS_APIC_VECTOR);
+	exiting_irq();
+}
+
 /*
  * This interrupt should never happen with our APIC/SMP architecture
  */
@@ -1978,6 +2011,15 @@ void smp_error_interrupt(struct pt_regs *regs)
 	exiting_irq();
 }
 
+void smp_trace_error_interrupt(struct pt_regs *regs)
+{
+	entering_irq();
+	trace_error_apic_entry(ERROR_APIC_VECTOR);
+	__smp_error_interrupt(regs);
+	trace_error_apic_exit(ERROR_APIC_VECTOR);
+	exiting_irq();
+}
+
 /**
  * connect_bsp_APIC - attach the APIC to the interrupt system
  */
diff --git a/arch/x86/kernel/cpu/common.c b/arch/x86/kernel/cpu/common.c
index 8f6a0f9..d9c8c09 100644
--- a/arch/x86/kernel/cpu/common.c
+++ b/arch/x86/kernel/cpu/common.c
@@ -1257,7 +1257,7 @@ void __cpuinit cpu_init(void)
 	switch_to_new_gdt(cpu);
 	loadsegment(fs, 0);
 
-	load_idt((const struct desc_ptr *)&idt_descr);
+	load_current_idt();
 
 	memset(me->thread.tls_array, 0, GDT_ENTRY_TLS_ENTRIES * 8);
 	syscall_init();
@@ -1334,7 +1334,7 @@ void __cpuinit cpu_init(void)
 	if (cpu_has_vme || cpu_has_tsc || cpu_has_de)
 		clear_in_cr4(X86_CR4_VME|X86_CR4_PVI|X86_CR4_TSD|X86_CR4_DE);
 
-	load_idt(&idt_descr);
+	load_current_idt();
 	switch_to_new_gdt(cpu);
 
 	/*
diff --git a/arch/x86/kernel/cpu/mcheck/therm_throt.c b/arch/x86/kernel/cpu/mcheck/therm_throt.c
index f6b35f2..2f3a799 100644
--- a/arch/x86/kernel/cpu/mcheck/therm_throt.c
+++ b/arch/x86/kernel/cpu/mcheck/therm_throt.c
@@ -29,6 +29,7 @@
 #include <asm/idle.h>
 #include <asm/mce.h>
 #include <asm/msr.h>
+#include <asm/trace/irq_vectors.h>
 
 /* How long to wait between reporting thermal events */
 #define CHECK_INTERVAL		(300 * HZ)
@@ -391,6 +392,15 @@ asmlinkage void smp_thermal_interrupt(struct pt_regs *regs)
 	exiting_ack_irq();
 }
 
+asmlinkage void smp_trace_thermal_interrupt(struct pt_regs *regs)
+{
+	entering_irq();
+	trace_thermal_apic_entry(THERMAL_APIC_VECTOR);
+	__smp_thermal_interrupt();
+	trace_thermal_apic_exit(THERMAL_APIC_VECTOR);
+	exiting_ack_irq();
+}
+
 /* Thermal monitoring depends on APIC, ACPI and clock modulation */
 static int intel_thermal_supported(struct cpuinfo_x86 *c)
 {
diff --git a/arch/x86/kernel/cpu/mcheck/threshold.c b/arch/x86/kernel/cpu/mcheck/threshold.c
index f20988a..fe6b1c8 100644
--- a/arch/x86/kernel/cpu/mcheck/threshold.c
+++ b/arch/x86/kernel/cpu/mcheck/threshold.c
@@ -8,6 +8,7 @@
 #include <asm/apic.h>
 #include <asm/idle.h>
 #include <asm/mce.h>
+#include <asm/trace/irq_vectors.h>
 
 static void default_threshold_interrupt(void)
 {
@@ -30,3 +31,11 @@ asmlinkage void smp_threshold_interrupt(void)
 	exiting_ack_irq();
 }
 
+asmlinkage void smp_trace_threshold_interrupt(void)
+{
+	entering_irq();
+	trace_threshold_apic_entry(THRESHOLD_APIC_VECTOR);
+	__smp_threshold_interrupt();
+	trace_threshold_apic_exit(THRESHOLD_APIC_VECTOR);
+	exiting_ack_irq();
+}
diff --git a/arch/x86/kernel/entry_32.S b/arch/x86/kernel/entry_32.S
index 8f3e2de..2cfbc3a 100644
--- a/arch/x86/kernel/entry_32.S
+++ b/arch/x86/kernel/entry_32.S
@@ -801,7 +801,17 @@ ENTRY(name)				\
 	CFI_ENDPROC;			\
 ENDPROC(name)
 
-#define BUILD_INTERRUPT(name, nr)	BUILD_INTERRUPT3(name, nr, smp_##name)
+
+#ifdef CONFIG_TRACING
+#define TRACE_BUILD_INTERRUPT(name, nr)		\
+	BUILD_INTERRUPT3(trace_##name, nr, smp_trace_##name)
+#else
+#define TRACE_BUILD_INTERRUPT(name, nr)
+#endif
+
+#define BUILD_INTERRUPT(name, nr) \
+	BUILD_INTERRUPT3(name, nr, smp_##name); \
+	TRACE_BUILD_INTERRUPT(name, nr)
 
 /* The include is where all of the SMP etc. interrupts come from */
 #include <asm/entry_arch.h>
diff --git a/arch/x86/kernel/entry_64.S b/arch/x86/kernel/entry_64.S
index 7272089..11eef43 100644
--- a/arch/x86/kernel/entry_64.S
+++ b/arch/x86/kernel/entry_64.S
@@ -1138,7 +1138,7 @@ END(common_interrupt)
 /*
  * APIC interrupts.
  */
-.macro apicinterrupt num sym do_sym
+.macro apicinterrupt3 num sym do_sym
 ENTRY(\sym)
 	INTR_FRAME
 	ASM_CLAC
@@ -1150,15 +1150,32 @@ ENTRY(\sym)
 END(\sym)
 .endm
 
+#ifdef CONFIG_TRACING
+#define trace(sym) trace_##sym
+#define smp_trace(sym) smp_trace_##sym
+
+.macro trace_apicinterrupt num sym
+apicinterrupt3 \num trace(\sym) smp_trace(\sym)
+.endm
+#else
+.macro trace_apicinterrupt num sym do_sym
+.endm
+#endif
+
+.macro apicinterrupt num sym do_sym
+apicinterrupt3 \num \sym \do_sym
+trace_apicinterrupt \num \sym
+.endm
+
 #ifdef CONFIG_SMP
-apicinterrupt IRQ_MOVE_CLEANUP_VECTOR \
+apicinterrupt3 IRQ_MOVE_CLEANUP_VECTOR \
 	irq_move_cleanup_interrupt smp_irq_move_cleanup_interrupt
-apicinterrupt REBOOT_VECTOR \
+apicinterrupt3 REBOOT_VECTOR \
 	reboot_interrupt smp_reboot_interrupt
 #endif
 
 #ifdef CONFIG_X86_UV
-apicinterrupt UV_BAU_MESSAGE \
+apicinterrupt3 UV_BAU_MESSAGE \
 	uv_bau_message_intr1 uv_bau_message_interrupt
 #endif
 apicinterrupt LOCAL_TIMER_VECTOR \
@@ -1167,7 +1184,7 @@ apicinterrupt X86_PLATFORM_IPI_VECTOR \
 	x86_platform_ipi smp_x86_platform_ipi
 
 #ifdef CONFIG_HAVE_KVM
-apicinterrupt POSTED_INTR_VECTOR \
+apicinterrupt3 POSTED_INTR_VECTOR \
 	kvm_posted_intr_ipi smp_kvm_posted_intr_ipi
 #endif
 
@@ -1451,13 +1468,13 @@ ENTRY(xen_failsafe_callback)
 	CFI_ENDPROC
 END(xen_failsafe_callback)
 
-apicinterrupt HYPERVISOR_CALLBACK_VECTOR \
+apicinterrupt3 HYPERVISOR_CALLBACK_VECTOR \
 	xen_hvm_callback_vector xen_evtchn_do_upcall
 
 #endif /* CONFIG_XEN */
 
 #if IS_ENABLED(CONFIG_HYPERV)
-apicinterrupt HYPERVISOR_CALLBACK_VECTOR \
+apicinterrupt3 HYPERVISOR_CALLBACK_VECTOR \
 	hyperv_callback_vector hyperv_vector_handler
 #endif /* CONFIG_HYPERV */
 
diff --git a/arch/x86/kernel/head_64.S b/arch/x86/kernel/head_64.S
index 84fb779..5e4d8a8 100644
--- a/arch/x86/kernel/head_64.S
+++ b/arch/x86/kernel/head_64.S
@@ -521,6 +521,12 @@ ENTRY(idt_table)
 ENTRY(debug_idt_table)
 	.skip IDT_ENTRIES * 16
 
+#ifdef CONFIG_TRACING
+	.align L1_CACHE_BYTES
+ENTRY(trace_idt_table)
+	.skip IDT_ENTRIES * 16
+#endif
+
 	__PAGE_ALIGNED_BSS
 NEXT_PAGE(empty_zero_page)
 	.skip PAGE_SIZE
diff --git a/arch/x86/kernel/irq.c b/arch/x86/kernel/irq.c
index e3b8df1..06af119 100644
--- a/arch/x86/kernel/irq.c
+++ b/arch/x86/kernel/irq.c
@@ -17,6 +17,7 @@
 #include <asm/idle.h>
 #include <asm/mce.h>
 #include <asm/hw_irq.h>
+#include <asm/trace/irq_vectors.h>
 
 atomic_t irq_err_count;
 
@@ -244,6 +245,18 @@ void smp_kvm_posted_intr_ipi(struct pt_regs *regs)
 }
 #endif
 
+void smp_trace_x86_platform_ipi(struct pt_regs *regs)
+{
+	struct pt_regs *old_regs = set_irq_regs(regs);
+
+	entering_ack_irq();
+	trace_x86_platform_ipi_entry(X86_PLATFORM_IPI_VECTOR);
+	__smp_x86_platform_ipi();
+	trace_x86_platform_ipi_exit(X86_PLATFORM_IPI_VECTOR);
+	exiting_irq();
+	set_irq_regs(old_regs);
+}
+
 EXPORT_SYMBOL_GPL(vector_used_by_percpu_irq);
 
 #ifdef CONFIG_HOTPLUG_CPU
diff --git a/arch/x86/kernel/irq_work.c b/arch/x86/kernel/irq_work.c
index 074d46f..636a55e 100644
--- a/arch/x86/kernel/irq_work.c
+++ b/arch/x86/kernel/irq_work.c
@@ -8,6 +8,7 @@
 #include <linux/irq_work.h>
 #include <linux/hardirq.h>
 #include <asm/apic.h>
+#include <asm/trace/irq_vectors.h>
 
 static inline void irq_work_entering_irq(void)
 {
@@ -28,6 +29,15 @@ void smp_irq_work_interrupt(struct pt_regs *regs)
 	exiting_irq();
 }
 
+void smp_trace_irq_work_interrupt(struct pt_regs *regs)
+{
+	irq_work_entering_irq();
+	trace_irq_work_entry(IRQ_WORK_VECTOR);
+	__smp_irq_work_interrupt();
+	trace_irq_work_exit(IRQ_WORK_VECTOR);
+	exiting_irq();
+}
+
 void arch_irq_work_raise(void)
 {
 #ifdef CONFIG_X86_LOCAL_APIC
diff --git a/arch/x86/kernel/smp.c b/arch/x86/kernel/smp.c
index d858375..f4fe0b8 100644
--- a/arch/x86/kernel/smp.c
+++ b/arch/x86/kernel/smp.c
@@ -30,6 +30,7 @@
 #include <asm/proto.h>
 #include <asm/apic.h>
 #include <asm/nmi.h>
+#include <asm/trace/irq_vectors.h>
 /*
  *	Some notes on x86 processor bugs affecting SMP operation:
  *
@@ -264,6 +265,17 @@ void smp_reschedule_interrupt(struct pt_regs *regs)
 	 */
 }
 
+void smp_trace_reschedule_interrupt(struct pt_regs *regs)
+{
+	ack_APIC_irq();
+	trace_reschedule_entry(RESCHEDULE_VECTOR);
+	__smp_reschedule_interrupt();
+	trace_reschedule_exit(RESCHEDULE_VECTOR);
+	/*
+	 * KVM uses this interrupt to force a cpu out of guest mode
+	 */
+}
+
 static inline void call_function_entering_irq(void)
 {
 	ack_APIC_irq();
@@ -283,6 +295,15 @@ void smp_call_function_interrupt(struct pt_regs *regs)
 	exiting_irq();
 }
 
+void smp_trace_call_function_interrupt(struct pt_regs *regs)
+{
+	call_function_entering_irq();
+	trace_call_function_entry(CALL_FUNCTION_VECTOR);
+	__smp_call_function_interrupt();
+	trace_call_function_exit(CALL_FUNCTION_VECTOR);
+	exiting_irq();
+}
+
 static inline void __smp_call_function_single_interrupt(void)
 {
 	generic_smp_call_function_single_interrupt();
@@ -296,6 +317,15 @@ void smp_call_function_single_interrupt(struct pt_regs *regs)
 	exiting_irq();
 }
 
+void smp_trace_call_function_single_interrupt(struct pt_regs *regs)
+{
+	call_function_entering_irq();
+	trace_call_function_single_entry(CALL_FUNCTION_SINGLE_VECTOR);
+	__smp_call_function_single_interrupt();
+	trace_call_function_single_exit(CALL_FUNCTION_SINGLE_VECTOR);
+	exiting_irq();
+}
+
 static int __init nonmi_ipi_setup(char *str)
 {
 	smp_no_nmi_ipi = true;
diff --git a/arch/x86/kernel/tracepoint.c b/arch/x86/kernel/tracepoint.c
new file mode 100644
index 0000000..1423efe
--- /dev/null
+++ b/arch/x86/kernel/tracepoint.c
@@ -0,0 +1,57 @@
+/*
+ * Code for supporting irq vector tracepoints.
+ *
+ * Copyright (C) 2013 Seiji Aguchi <sei...@hd...>
+ *
+ */
+#include <asm/hw_irq.h>
+#include <asm/desc.h>
+#include <linux/atomic.h>
+
+atomic_t trace_idt_ctr = ATOMIC_INIT(0);
+struct desc_ptr trace_idt_descr = { NR_VECTORS * 16 - 1,
+				(unsigned long) trace_idt_table };
+
+#ifndef CONFIG_X86_64
+gate_desc trace_idt_table[NR_VECTORS] __page_aligned_data
+					= { { { { 0, 0 } } }, };
+#endif
+
+static int trace_irq_vector_refcount;
+static DEFINE_MUTEX(irq_vector_mutex);
+
+static void set_trace_idt_ctr(int val)
+{
+	atomic_set(&trace_idt_ctr, val);
+	/* Ensure the trace_idt_ctr is set before sending IPI */
+	wmb();
+}
+
+static void switch_idt(void *arg)
+{
+	load_current_idt();
+}
+
+void trace_irq_vector_regfunc(void)
+{
+	mutex_lock(&irq_vector_mutex);
+	if (!trace_irq_vector_refcount) {
+		set_trace_idt_ctr(1);
+		smp_call_function(switch_idt, NULL, 0);
+		switch_idt(NULL);
+	}
+	trace_irq_vector_refcount++;
+	mutex_unlock(&irq_vector_mutex);
+}
+
+void trace_irq_vector_unregfunc(void)
+{
+	mutex_lock(&irq_vector_mutex);
+	trace_irq_vector_refcount--;
+	if (!trace_irq_vector_refcount) {
+		set_trace_idt_ctr(0);
+		smp_call_function(switch_idt, NULL, 0);
+		switch_idt(NULL);
+	}
+	mutex_unlock(&irq_vector_mutex);
+}
diff --git a/include/xen/events.h b/include/xen/events.h
index b2b27c6..c9ea10e 100644
--- a/include/xen/events.h
+++ b/include/xen/events.h
@@ -76,6 +76,9 @@ unsigned irq_from_evtchn(unsigned int evtchn);
 
 /* Xen HVM evtchn vector callback */
 void xen_hvm_callback_vector(void);
+#ifdef CONFIG_TRACING
+#define trace_xen_hvm_callback_vector xen_hvm_callback_vector
+#endif
 extern int xen_have_vector_callback;
 int xen_set_callback_via(uint64_t via);
 void xen_evtchn_do_upcall(struct pt_regs *regs);
-- 
1.7.1

[Dle-develop] [PATCH v17 3/4] x86: Rename variables for debugging

[Seiji A. <sei...@hd...>]

Rename variables for debugging to describe meaning of them precisely.

Also, introduce a generic way to switch IDT by checking a current state,
debug on/off.

Signed-off-by: Seiji Aguchi <sei...@hd...>
---
 arch/x86/include/asm/desc.h  |   47 +++++++++++++++++++++++++++++++++++++++--
 arch/x86/kernel/cpu/common.c |   16 +++++++-------
 arch/x86/kernel/head_64.S    |    2 +-
 arch/x86/kernel/traps.c      |    2 +-
 4 files changed, 54 insertions(+), 13 deletions(-)

diff --git a/arch/x86/include/asm/desc.h b/arch/x86/include/asm/desc.h
index 8bf1c06..af290b8 100644
--- a/arch/x86/include/asm/desc.h
+++ b/arch/x86/include/asm/desc.h
@@ -36,8 +36,8 @@ static inline void fill_ldt(struct desc_struct *desc, const struct user_desc *in
 
 extern struct desc_ptr idt_descr;
 extern gate_desc idt_table[];
-extern struct desc_ptr nmi_idt_descr;
-extern gate_desc nmi_idt_table[];
+extern struct desc_ptr debug_idt_descr;
+extern gate_desc debug_idt_table[];
 
 struct gdt_page {
 	struct desc_struct gdt[GDT_ENTRIES];
@@ -316,7 +316,7 @@ static inline void set_nmi_gate(int gate, void *addr)
 	gate_desc s;
 
 	pack_gate(&s, GATE_INTERRUPT, (unsigned long)addr, 0, 0, __KERNEL_CS);
-	write_idt_entry(nmi_idt_table, gate, &s);
+	write_idt_entry(debug_idt_table, gate, &s);
 }
 #endif
 
@@ -405,4 +405,45 @@ static inline void set_system_intr_gate_ist(int n, void *addr, unsigned ist)
 	_set_gate(n, GATE_INTERRUPT, addr, 0x3, ist, __KERNEL_CS);
 }
 
+#ifdef CONFIG_X86_64
+DECLARE_PER_CPU(u32, debug_idt_ctr);
+static inline bool is_debug_idt_enabled(void)
+{
+	if (this_cpu_read(debug_idt_ctr))
+		return true;
+
+	return false;
+}
+
+static inline void load_debug_idt(void)
+{
+	load_idt((const struct desc_ptr *)&debug_idt_descr);
+}
+#else
+static inline bool is_debug_idt_enabled(void)
+{
+	return false;
+}
+
+static inline void load_debug_idt(void)
+{
+}
+#endif
+
+/*
+ * the load_current_idt() is called with interrupt disabled by local_irq_save()
+ * to avoid races. That way the IDT will always be set back to the expected
+ * descriptor.
+ */
+static inline void load_current_idt(void)
+{
+	unsigned long flags;
+
+	local_irq_save(flags);
+	if (is_debug_idt_enabled())
+		load_debug_idt();
+	else
+		load_idt((const struct desc_ptr *)&idt_descr);
+	local_irq_restore(flags);
+}
 #endif /* _ASM_X86_DESC_H */
diff --git a/arch/x86/kernel/cpu/common.c b/arch/x86/kernel/cpu/common.c
index 22018f7..8f6a0f9 100644
--- a/arch/x86/kernel/cpu/common.c
+++ b/arch/x86/kernel/cpu/common.c
@@ -1071,8 +1071,8 @@ __setup("clearcpuid=", setup_disablecpuid);
 
 #ifdef CONFIG_X86_64
 struct desc_ptr idt_descr = { NR_VECTORS * 16 - 1, (unsigned long) idt_table };
-struct desc_ptr nmi_idt_descr = { NR_VECTORS * 16 - 1,
-				    (unsigned long) nmi_idt_table };
+struct desc_ptr debug_idt_descr = { NR_VECTORS * 16 - 1,
+				    (unsigned long) debug_idt_table };
 
 DEFINE_PER_CPU_FIRST(union irq_stack_union,
 		     irq_stack_union) __aligned(PAGE_SIZE);
@@ -1148,20 +1148,20 @@ int is_debug_stack(unsigned long addr)
 		 addr > (__get_cpu_var(debug_stack_addr) - DEBUG_STKSZ));
 }
 
-static DEFINE_PER_CPU(u32, debug_stack_use_ctr);
+DEFINE_PER_CPU(u32, debug_idt_ctr);
 
 void debug_stack_set_zero(void)
 {
-	this_cpu_inc(debug_stack_use_ctr);
-	load_idt((const struct desc_ptr *)&nmi_idt_descr);
+	this_cpu_inc(debug_idt_ctr);
+	load_current_idt();
 }
 
 void debug_stack_reset(void)
 {
-	if (WARN_ON(!this_cpu_read(debug_stack_use_ctr)))
+	if (WARN_ON(!this_cpu_read(debug_idt_ctr)))
 		return;
-	if (this_cpu_dec_return(debug_stack_use_ctr) == 0)
-		load_idt((const struct desc_ptr *)&idt_descr);
+	if (this_cpu_dec_return(debug_idt_ctr) == 0)
+		load_current_idt();
 }
 
 #else	/* CONFIG_X86_64 */
diff --git a/arch/x86/kernel/head_64.S b/arch/x86/kernel/head_64.S
index 321d65e..84fb779 100644
--- a/arch/x86/kernel/head_64.S
+++ b/arch/x86/kernel/head_64.S
@@ -518,7 +518,7 @@ ENTRY(idt_table)
 	.skip IDT_ENTRIES * 16
 
 	.align L1_CACHE_BYTES
-ENTRY(nmi_idt_table)
+ENTRY(debug_idt_table)
 	.skip IDT_ENTRIES * 16
 
 	__PAGE_ALIGNED_BSS
diff --git a/arch/x86/kernel/traps.c b/arch/x86/kernel/traps.c
index 772e2a8..d27182d 100644
--- a/arch/x86/kernel/traps.c
+++ b/arch/x86/kernel/traps.c
@@ -785,7 +785,7 @@ void __init trap_init(void)
 	x86_init.irqs.trap_init();
 
 #ifdef CONFIG_X86_64
-	memcpy(&nmi_idt_table, &idt_table, IDT_ENTRIES * 16);
+	memcpy(&debug_idt_table, &idt_table, IDT_ENTRIES * 16);
 	set_nmi_gate(X86_TRAP_DB, &debug);
 	set_nmi_gate(X86_TRAP_BP, &int3);
 #endif
-- 
1.7.1

[Dle-develop] [PATCH v17 2/4] trace, x86: Introduce entering/exiting_irq()

[Seiji A. <sei...@hd...>]

When implementing tracepoints in interrupt handers, if the tracepoints are
simply added in the performance sensitive path of interrupt handers,
it may cause potential performance problem due to the time penalty.

To solve the problem, an idea is to prepare non-trace/trace irq handers and
switch their IDTs at the enabling/disabling time.

So, let's introduce entering_irq()/exiting_irq() for pre/post-
processing of each irq handler.

A way to use them is as follows.

Non-trace irq handler:
smp_irq_handler()
{
	entering_irq();		/* pre-processing of this handler */
	__smp_irq_handler();	/*
				 * common logic between non-trace and trace handlers
				 * in a vector.
				 */
	exiting_irq();		/* post-processing of this handler */

}

Trace irq_handler:
smp_trace_irq_handler()
{
	entering_irq();		/* pre-processing of this handler */
	trace_irq_entry();	/* tracepoint for irq entry */
	__smp_irq_handler();	/*
				 * common logic between non-trace and trace handlers
				 * in a vector.
				 */
	trace_irq_exit();	/* tracepoint for irq exit */
	exiting_irq();		/* post-processing of this handler */

}

If tracepoints can place outside entering_irq()/exiting_irq() as follows,
it looks cleaner.

smp_trace_irq_handler()
{
	trace_irq_entry();
	smp_irq_handler();
	trace_irq_exit();
}

But it doesn't work.
The problem is with irq_enter/exit() being called. They must be called before
trace_irq_enter/exit(),  because of the rcu_irq_enter() must be called before
any tracepoints are used, as tracepoints use  rcu to synchronize.

As a possible alternative, we may be able to call irq_enter() first as follows
if irq_enter() can nest.

smp_trace_irq_hander()
{
	irq_entry();
	trace_irq_entry();
	smp_irq_handler();
	trace_irq_exit();
	irq_exit();
}

But it doesn't work, either.
If irq_enter() is nested, it may have a time penalty because it has to check if it
was already called or not. The time penalty is not desired in performance sensitive
paths even if it is tiny.

Signed-off-by: Seiji Aguchi <sei...@hd...>
---
 arch/x86/include/asm/apic.h              |   27 +++++++++++++++++++++++
 arch/x86/kernel/apic/apic.c              |   33 ++++++++++++++++------------
 arch/x86/kernel/cpu/mcheck/therm_throt.c |   14 ++++++-----
 arch/x86/kernel/cpu/mcheck/threshold.c   |   15 +++++++-----
 arch/x86/kernel/irq.c                    |   18 ++++++--------
 arch/x86/kernel/irq_work.c               |   14 ++++++++++-
 arch/x86/kernel/smp.c                    |   35 +++++++++++++++++++++++------
 7 files changed, 110 insertions(+), 46 deletions(-)

diff --git a/arch/x86/include/asm/apic.h b/arch/x86/include/asm/apic.h
index 3388034..f8119b5 100644
--- a/arch/x86/include/asm/apic.h
+++ b/arch/x86/include/asm/apic.h
@@ -12,6 +12,7 @@
 #include <asm/fixmap.h>
 #include <asm/mpspec.h>
 #include <asm/msr.h>
+#include <asm/idle.h>
 
 #define ARCH_APICTIMER_STOPS_ON_C3	1
 
@@ -687,5 +688,31 @@ extern int default_check_phys_apicid_present(int phys_apicid);
 #endif
 
 #endif /* CONFIG_X86_LOCAL_APIC */
+extern void irq_enter(void);
+extern void irq_exit(void);
+
+static inline void entering_irq(void)
+{
+	irq_enter();
+	exit_idle();
+}
+
+static inline void entering_ack_irq(void)
+{
+	ack_APIC_irq();
+	entering_irq();
+}
+
+static inline void exiting_irq(void)
+{
+	irq_exit();
+}
+
+static inline void exiting_ack_irq(void)
+{
+	irq_exit();
+	/* Ack only at the end to avoid potential reentry */
+	ack_APIC_irq();
+}
 
 #endif /* _ASM_X86_APIC_H */
diff --git a/arch/x86/kernel/apic/apic.c b/arch/x86/kernel/apic/apic.c
index 904611b..59ee76f 100644
--- a/arch/x86/kernel/apic/apic.c
+++ b/arch/x86/kernel/apic/apic.c
@@ -919,17 +919,14 @@ void __irq_entry smp_apic_timer_interrupt(struct pt_regs *regs)
 	/*
 	 * NOTE! We'd better ACK the irq immediately,
 	 * because timer handling can be slow.
-	 */
-	ack_APIC_irq();
-	/*
+	 *
 	 * update_process_times() expects us to have done irq_enter().
 	 * Besides, if we don't timer interrupts ignore the global
 	 * interrupt lock, which is the WrongThing (tm) to do.
 	 */
-	irq_enter();
-	exit_idle();
+	entering_ack_irq();
 	local_apic_timer_interrupt();
-	irq_exit();
+	exiting_irq();
 
 	set_irq_regs(old_regs);
 }
@@ -1907,12 +1904,10 @@ int __init APIC_init_uniprocessor(void)
 /*
  * This interrupt should _never_ happen with our APIC/SMP architecture
  */
-void smp_spurious_interrupt(struct pt_regs *regs)
+static inline void __smp_spurious_interrupt(void)
 {
 	u32 v;
 
-	irq_enter();
-	exit_idle();
 	/*
 	 * Check if this really is a spurious interrupt and ACK it
 	 * if it is a vectored one.  Just in case...
@@ -1927,13 +1922,19 @@ void smp_spurious_interrupt(struct pt_regs *regs)
 	/* see sw-dev-man vol 3, chapter 7.4.13.5 */
 	pr_info("spurious APIC interrupt on CPU#%d, "
 		"should never happen.\n", smp_processor_id());
-	irq_exit();
+}
+
+void smp_spurious_interrupt(struct pt_regs *regs)
+{
+	entering_irq();
+	__smp_spurious_interrupt();
+	exiting_irq();
 }
 
 /*
  * This interrupt should never happen with our APIC/SMP architecture
  */
-void smp_error_interrupt(struct pt_regs *regs)
+static inline void __smp_error_interrupt(struct pt_regs *regs)
 {
 	u32 v0, v1;
 	u32 i = 0;
@@ -1948,8 +1949,6 @@ void smp_error_interrupt(struct pt_regs *regs)
 		"Illegal register address",	/* APIC Error Bit 7 */
 	};
 
-	irq_enter();
-	exit_idle();
 	/* First tickle the hardware, only then report what went on. -- REW */
 	v0 = apic_read(APIC_ESR);
 	apic_write(APIC_ESR, 0);
@@ -1970,7 +1969,13 @@ void smp_error_interrupt(struct pt_regs *regs)
 
 	apic_printk(APIC_DEBUG, KERN_CONT "\n");
 
-	irq_exit();
+}
+
+void smp_error_interrupt(struct pt_regs *regs)
+{
+	entering_irq();
+	__smp_error_interrupt(regs);
+	exiting_irq();
 }
 
 /**
diff --git a/arch/x86/kernel/cpu/mcheck/therm_throt.c b/arch/x86/kernel/cpu/mcheck/therm_throt.c
index 47a1870..f6b35f2 100644
--- a/arch/x86/kernel/cpu/mcheck/therm_throt.c
+++ b/arch/x86/kernel/cpu/mcheck/therm_throt.c
@@ -378,15 +378,17 @@ static void unexpected_thermal_interrupt(void)
 
 static void (*smp_thermal_vector)(void) = unexpected_thermal_interrupt;
 
-asmlinkage void smp_thermal_interrupt(struct pt_regs *regs)
+static inline void __smp_thermal_interrupt(void)
 {
-	irq_enter();
-	exit_idle();
 	inc_irq_stat(irq_thermal_count);
 	smp_thermal_vector();
-	irq_exit();
-	/* Ack only at the end to avoid potential reentry */
-	ack_APIC_irq();
+}
+
+asmlinkage void smp_thermal_interrupt(struct pt_regs *regs)
+{
+	entering_irq();
+	__smp_thermal_interrupt();
+	exiting_ack_irq();
 }
 
 /* Thermal monitoring depends on APIC, ACPI and clock modulation */
diff --git a/arch/x86/kernel/cpu/mcheck/threshold.c b/arch/x86/kernel/cpu/mcheck/threshold.c
index aa578ca..f20988a 100644
--- a/arch/x86/kernel/cpu/mcheck/threshold.c
+++ b/arch/x86/kernel/cpu/mcheck/threshold.c
@@ -17,13 +17,16 @@ static void default_threshold_interrupt(void)
 
 void (*mce_threshold_vector)(void) = default_threshold_interrupt;
 
-asmlinkage void smp_threshold_interrupt(void)
+static inline void __smp_threshold_interrupt(void)
 {
-	irq_enter();
-	exit_idle();
 	inc_irq_stat(irq_threshold_count);
 	mce_threshold_vector();
-	irq_exit();
-	/* Ack only at the end to avoid potential reentry */
-	ack_APIC_irq();
 }
+
+asmlinkage void smp_threshold_interrupt(void)
+{
+	entering_irq();
+	__smp_threshold_interrupt();
+	exiting_ack_irq();
+}
+
diff --git a/arch/x86/kernel/irq.c b/arch/x86/kernel/irq.c
index ac0631d..e3b8df1 100644
--- a/arch/x86/kernel/irq.c
+++ b/arch/x86/kernel/irq.c
@@ -204,23 +204,21 @@ unsigned int __irq_entry do_IRQ(struct pt_regs *regs)
 /*
  * Handler for X86_PLATFORM_IPI_VECTOR.
  */
-void smp_x86_platform_ipi(struct pt_regs *regs)
+void __smp_x86_platform_ipi(void)
 {
-	struct pt_regs *old_regs = set_irq_regs(regs);
-
-	ack_APIC_irq();
-
-	irq_enter();
-
-	exit_idle();
-
 	inc_irq_stat(x86_platform_ipis);
 
 	if (x86_platform_ipi_callback)
 		x86_platform_ipi_callback();
+}
 
-	irq_exit();
+void smp_x86_platform_ipi(struct pt_regs *regs)
+{
+	struct pt_regs *old_regs = set_irq_regs(regs);
 
+	entering_ack_irq();
+	__smp_x86_platform_ipi();
+	exiting_irq();
 	set_irq_regs(old_regs);
 }
 
diff --git a/arch/x86/kernel/irq_work.c b/arch/x86/kernel/irq_work.c
index ca8f703..074d46f 100644
--- a/arch/x86/kernel/irq_work.c
+++ b/arch/x86/kernel/irq_work.c
@@ -9,13 +9,23 @@
 #include <linux/hardirq.h>
 #include <asm/apic.h>
 
-void smp_irq_work_interrupt(struct pt_regs *regs)
+static inline void irq_work_entering_irq(void)
 {
 	irq_enter();
 	ack_APIC_irq();
+}
+
+static inline void __smp_irq_work_interrupt(void)
+{
 	inc_irq_stat(apic_irq_work_irqs);
 	irq_work_run();
-	irq_exit();
+}
+
+void smp_irq_work_interrupt(struct pt_regs *regs)
+{
+	irq_work_entering_irq();
+	__smp_irq_work_interrupt();
+	exiting_irq();
 }
 
 void arch_irq_work_raise(void)
diff --git a/arch/x86/kernel/smp.c b/arch/x86/kernel/smp.c
index 48d2b7d..d858375 100644
--- a/arch/x86/kernel/smp.c
+++ b/arch/x86/kernel/smp.c
@@ -249,32 +249,51 @@ finish:
 /*
  * Reschedule call back.
  */
-void smp_reschedule_interrupt(struct pt_regs *regs)
+static inline void __smp_reschedule_interrupt(void)
 {
-	ack_APIC_irq();
 	inc_irq_stat(irq_resched_count);
 	scheduler_ipi();
+}
+
+void smp_reschedule_interrupt(struct pt_regs *regs)
+{
+	ack_APIC_irq();
+	__smp_reschedule_interrupt();
 	/*
 	 * KVM uses this interrupt to force a cpu out of guest mode
 	 */
 }
 
-void smp_call_function_interrupt(struct pt_regs *regs)
+static inline void call_function_entering_irq(void)
 {
 	ack_APIC_irq();
 	irq_enter();
+}
+
+static inline void __smp_call_function_interrupt(void)
+{
 	generic_smp_call_function_interrupt();
 	inc_irq_stat(irq_call_count);
-	irq_exit();
 }
 
-void smp_call_function_single_interrupt(struct pt_regs *regs)
+void smp_call_function_interrupt(struct pt_regs *regs)
+{
+	call_function_entering_irq();
+	__smp_call_function_interrupt();
+	exiting_irq();
+}
+
+static inline void __smp_call_function_single_interrupt(void)
 {
-	ack_APIC_irq();
-	irq_enter();
 	generic_smp_call_function_single_interrupt();
 	inc_irq_stat(irq_call_count);
-	irq_exit();
+}
+
+void smp_call_function_single_interrupt(struct pt_regs *regs)
+{
+	call_function_entering_irq();
+	__smp_call_function_single_interrupt();
+	exiting_irq();
 }
 
 static int __init nonmi_ipi_setup(char *str)
-- 
1.7.1

[Dle-develop] [PATCH v17 1/4] tracing: Add DEFINE_EVENT_FN() macro

[Seiji A. <sei...@hd...>]

From: Steven Rostedt <ro...@go...>

Each TRACE_EVENT() adds several helper functions. If two or more trace events
share the same structure and print format, they can also share most of these
helper functions and save a lot of space from duplicate code. This is why the
DECLARE_EVENT_CLASS() and DEFINE_EVENT() were created.

Some events require a trigger to be called at registering and unregistering of
the event and to do so they use TRACE_EVENT_FN().

If multiple events require a trigger, they currently have no choice but to use
TRACE_EVENT_FN() as there's no DEFINE_EVENT_FN() available. This unfortunately
causes a lot of wasted duplicate code created.

By adding a DEFINE_EVENT_FN(), these events can still use a
DECLARE_EVENT_CLASS() and then define their own triggers.

Signed-off-by: Steven Rostedt <ro...@go...>
Signed-off-by: Seiji Aguchi <sei...@hd...>
---
 include/linux/tracepoint.h   |    2 ++
 include/trace/define_trace.h |    5 +++++
 include/trace/ftrace.h       |    4 ++++
 3 files changed, 11 insertions(+), 0 deletions(-)

diff --git a/include/linux/tracepoint.h b/include/linux/tracepoint.h
index f8e084d..ebeab36 100644
--- a/include/linux/tracepoint.h
+++ b/include/linux/tracepoint.h
@@ -378,6 +378,8 @@ static inline void tracepoint_synchronize_unregister(void)
 #define DECLARE_EVENT_CLASS(name, proto, args, tstruct, assign, print)
 #define DEFINE_EVENT(template, name, proto, args)		\
 	DECLARE_TRACE(name, PARAMS(proto), PARAMS(args))
+#define DEFINE_EVENT_FN(template, name, proto, args, reg, unreg)\
+	DECLARE_TRACE(name, PARAMS(proto), PARAMS(args))
 #define DEFINE_EVENT_PRINT(template, name, proto, args, print)	\
 	DECLARE_TRACE(name, PARAMS(proto), PARAMS(args))
 #define DEFINE_EVENT_CONDITION(template, name, proto,		\
diff --git a/include/trace/define_trace.h b/include/trace/define_trace.h
index 1905ca8..02e1003 100644
--- a/include/trace/define_trace.h
+++ b/include/trace/define_trace.h
@@ -44,6 +44,10 @@
 #define DEFINE_EVENT(template, name, proto, args) \
 	DEFINE_TRACE(name)
 
+#undef DEFINE_EVENT_FN
+#define DEFINE_EVENT_FN(template, name, proto, args, reg, unreg) \
+	DEFINE_TRACE_FN(name, reg, unreg)
+
 #undef DEFINE_EVENT_PRINT
 #define DEFINE_EVENT_PRINT(template, name, proto, args, print)	\
 	DEFINE_TRACE(name)
@@ -91,6 +95,7 @@
 #undef TRACE_EVENT_CONDITION
 #undef DECLARE_EVENT_CLASS
 #undef DEFINE_EVENT
+#undef DEFINE_EVENT_FN
 #undef DEFINE_EVENT_PRINT
 #undef DEFINE_EVENT_CONDITION
 #undef TRACE_HEADER_MULTI_READ
diff --git a/include/trace/ftrace.h b/include/trace/ftrace.h
index 19edd7f..d615f78 100644
--- a/include/trace/ftrace.h
+++ b/include/trace/ftrace.h
@@ -71,6 +71,10 @@
 	static struct ftrace_event_call	__used		\
 	__attribute__((__aligned__(4))) event_##name
 
+#undef DEFINE_EVENT_FN
+#define DEFINE_EVENT_FN(template, name, proto, args, reg, unreg)	\
+	DEFINE_EVENT(template, name, PARAMS(proto), PARAMS(args))
+
 #undef DEFINE_EVENT_PRINT
 #define DEFINE_EVENT_PRINT(template, name, proto, args, print)	\
 	DEFINE_EVENT(template, name, PARAMS(proto), PARAMS(args))
-- 
1.7.1

[Dle-develop] [PATCH v17 0/4] trace, x86: irq vector tracepoint support

[Seiji A. <sei...@hd...>]

Change log
  v16 -> v17
 - Patch 4/4
   - Check if trace_idt is enabled only when debug_idt is disabled 
     in load_current_idt().(Reported by Steven Rostedt)
   - Confirmed that a function tracer selftest passed successfully.

  v15 -> v16
 - Patch 4/4
   - Define trace_uv_bau_message_intr1 in case of CONFIG_TRACING=y
     to build with SGI UV support successfully.
   - Define trace_hyperv_callback_vector only when CONFIG_TRACING
     is enabled.
  v14 -> v15
 - Patch 2/4
   Introduce non-trace irq handlers with entering/exiting_irq()
   by separating it from previous "patch v14 3/3".

 - Patch 3/4
   Separate a patch renaming variables for debugging and introducing 
   load_current_idt() from previous "patch v14 3/3".

 - Patch 4/4
   Introduce load_current_idt() to cpu_init() for i386 to handle cpu-hotplug.

 v13 -> v14
 - Rebase to 3.10-rc4
 - Patch 3/3
   - Add comments above load_current_idt() in arch/x86/include/asm/desc.h.
   - Introduce a logic selecting IDT that we currently should be using,
     based on the current state instead of current_idt_desc_ptr.
   - Rename some "nmi" variables to "debug".
   - Introduce local_irq_save/restore() in load_current_idt() to avoid races
     regardless of process/interrupt context.

 v12 -> v13
 - Rebase to 3.10-rc3
 - Patch 2/3
   - Separate a patch introducing entering/exiting_irq() from patch-v12 3/3.
 - Patch 3/3
   - Introduce write_trace_idt_entry() to remove "ifdef CONFIG_TRACING"
     from _set_gate().
   - Change DEFINE_IRQ_VECTOR_EVENT to save on repeat code.
   - Add a path of irq_vector.h to Makefile.
   - Introduce current_idt_descr_ptr and load_current_idt() to switch
     IDT in a generic way with handling Debug traps/NMI and cpu hotplug.

 v11 -> v12
 - Rebase to 3.9-rc5

 v10 -> v11
 - Rebase to 3.9-rc2
 - Add a modification for hyperv_callback vector. (patch 2/3)
 - Change a way to switch idt to check the table in use instead of saving/restoring it,
   because saving/restoring functions will break if we have to add another one. (patch 2/3)

 v9 -> v10
 - Add an explanation the reason why tracepoints has to place inside irq enter/exit handling. (patch 3/3)

 v8 -> v9
 - Rebase to 3.8-rc6
 - Add Steven's email address at the top of the message and 
   move my signed-off-by below Steven's one because it is
   originally created by Steven. (patch 1/3)
 - Introduce a irq_vector_mutex to avoid a race at registering/unregistering
   time. (patch 2/3)
 - Use a per_cpu data to orig_idt_descr because IDT descritor is needed to each cpu
   and the appropriate data type is per_cpu data. It is suggested by Steven.
   (patch 2/3)

 v7 -> v8
 - Rebase to 3.8-rc4
 - Add a patch 1 introducing DEFINE_EVENT_FN() macro.
 - Rename original patches 1 and 2 to 2 and 3.
 - Change a definition of tracepoint to use DEFINE_EVENT_FN(). (patch 2)
 - Change alloc_intr_gate() to use do{}while(0) to avoid a warning 
   of checkpatch.pl. (patch 2)
 - Move entering_irq()/exiting_irq() to arch/x86/include/asm/apic.h (patch 3)

 v6 -> v7
 - Divide into two patches to make a code review easier.
   Summery of each patch is as follows.
    - Patch 1/2
      - Add an irq_vector tracing infrastructure.
      - Create idt_table for tracing. It is refactored to avoid duplicating
        existing logic.
      - Duplicate new irq handlers inserted tracepoints.

    - Patch 2/2
      - Share a common logic among irq handlers to make them
        manageable and readable.

 v5 -> v6
 - Rebased to 3.7

 v4 -> v5
 - Rebased to 3.6.0

 - Introduce a logic switching IDT at enabling/disabling TP time 
   so that a time penalty makes a zero when tracepoints are disabled.
   This IDT is created only when CONFIG_TRACEPOINTS is enabled.

 - Remove arch_irq_vector_entry/exit and add followings again
   so that we can add each tracepoint in a generic way.
   - error_apic_vector
   - thermal_apic_vector
   - threshold_apic_vector
   - spurious_apic_vector
   - x86_platform_ipi_vector

 - Drop nmi tracepoints to begin with apic interrupts and discuss a logic switching
   IDT first.

 - Move irq_vectors.h in the directory of arch/x86/include/asm/trace because
   I'm not sure if a logic switching IDT is sharable with other architectures.

 v3 -> v4
 - Add a latency measurement of each tracepoint
 - Rebased to 3.6-rc6

 v2 -> v3
 - Remove an invalidate_tlb_vector event because it was replaced by a call function vector
   in a following commit.
   http://git.kernel.org/?p=linux/kernel/git/torvalds/linux.git;a=commit;h=52aec3308db85f4e9f5c8b9f5dc4fbd0138c6fa4

 v1 -> v2
 - Modify variable name from irq to vector.
 - Merge arch-specific tracepoints below to an arch_irq_vector_entry/exit.
   - error_apic_vector
   - thermal_apic_vector
   - threshold_apic_vector
   - spurious_apic_vector
   - x86_platform_ipi_vector

[Purpose of this patch]

As Vaibhav explained in the thread below, tracepoints for irq vectors are useful.

http://www.spinics.net/lists/mm-commits/msg85707.html

<snip>
The current interrupt traces from irq_handler_entry and irq_handler_exit provide
when an interrupt is handled.  
They provide good data about when the system has switched to kernel space and 
how it affects the currently running processes.

There are some IRQ vectors which trigger the system into kernel space, which are 
not handled in generic IRQ handlers.  
Tracing such events gives us the information about IRQ interaction with other 
system events.

The trace also tells where the system is spending its time.  We want to know which
cores are handling interrupts and 
how they are affecting other processes in the system.  Also, the trace provides
information about when the cores are 
idle and which interrupts are changing that state.
<snip>

On the other hand, my usecase is tracing just local timer event and getting
 a value of instruction pointer.

I suggested to add an argument local timer event to get instruction pointer before.
But there is another way to get it with external module like systemtap.
So, I don't need to add any argument to irq vector tracepoints now.

[Patch Description]

Vaibhav's patch shared a trace point ,irq_vector_entry/irq_vector_exit, in all events.
But there is an above use case to trace specific irq_vector rather than tracing all events.
In this case, we are concerned about overhead due to unwanted events.

This patch adds following tracepoints instead of introducing irq_vector_entry/exit.
so that we can enable them independently.
   - local_timer_vector
   - reschedule_vector
   - call_function_vector
   - call_function_single_vector 
   - irq_work_entry_vector
   - error_apic_vector
   - thermal_apic_vector
   - threshold_apic_vector
   - spurious_apic_vector
   - x86_platform_ipi_vector

Seiji Aguchi (3):
  trace,x86: Introduce entering/exiting_irq()
  x86: Rename variables for debugging
  trace,x86: Add irq vector tracepoints

Steven Rostedt (1):
  tracing: Add DEFINE_EVENT_FN() macro

 arch/x86/include/asm/apic.h              |   27 +++++++
 arch/x86/include/asm/desc.h              |  119 ++++++++++++++++++++++++++++-
 arch/x86/include/asm/entry_arch.h        |    8 +-
 arch/x86/include/asm/hw_irq.h            |   17 ++++
 arch/x86/include/asm/mshyperv.h          |    3 +
 arch/x86/include/asm/trace/irq_vectors.h |  104 ++++++++++++++++++++++++++
 arch/x86/include/asm/uv/uv_bau.h         |    3 +
 arch/x86/kernel/Makefile                 |    1 +
 arch/x86/kernel/apic/Makefile            |    1 +
 arch/x86/kernel/apic/apic.c              |   71 +++++++++++++++---
 arch/x86/kernel/cpu/common.c             |   20 +++---
 arch/x86/kernel/cpu/mcheck/therm_throt.c |   24 +++++--
 arch/x86/kernel/cpu/mcheck/threshold.c   |   24 +++++--
 arch/x86/kernel/entry_32.S               |   12 +++-
 arch/x86/kernel/entry_64.S               |   31 ++++++--
 arch/x86/kernel/head_64.S                |    8 ++-
 arch/x86/kernel/irq.c                    |   31 +++++---
 arch/x86/kernel/irq_work.c               |   24 ++++++-
 arch/x86/kernel/smp.c                    |   65 ++++++++++++++--
 arch/x86/kernel/tracepoint.c             |   57 ++++++++++++++
 arch/x86/kernel/traps.c                  |    2 +-
 include/linux/tracepoint.h               |    2 +
 include/trace/define_trace.h             |    5 +
 include/trace/ftrace.h                   |    4 +
 include/xen/events.h                     |    3 +
 25 files changed, 594 insertions(+), 72 deletions(-)
 create mode 100644 arch/x86/include/asm/trace/irq_vectors.h
 create mode 100644 arch/x86/kernel/tracepoint.c

Re: [Dle-develop] [PATCH v16 4/4] trace, x86: Add irq vector tracepoints

[Seiji A. <sei...@hd...>]

> On Tue, 2013-06-18 at 15:01 -0400, Seiji Aguchi wrote:
> >  /*
> >   * the load_current_idt() is called with interrupt disabled by
> > local_irq_save()
> >   * to avoid races. That way the IDT will always be set back to the
> > expected
> > @@ -442,6 +508,8 @@ static inline void load_current_idt(void)
> >         local_irq_save(flags);
> >         if (is_debug_idt_enabled())
> >                 load_debug_idt();
> > +       if (is_trace_idt_enabled())
> > +               load_trace_idt();
> 
> This should be:
> 
> 	else if (is_trace_idt_enabled())
> 
> Otherwise, you just totally negated the previous if.

Thank you for testing my patch.
I will fix it.

Seiji

Re: [Dle-develop] [PATCH v16 4/4] trace, x86: Add irq vector tracepoints

[Steven R. <ro...@go...>]

The function tracer self test would crash hard after applying this
patch. I found the bug:



On Tue, 2013-06-18 at 15:01 -0400, Seiji Aguchi wrote:
>  /*
>   * the load_current_idt() is called with interrupt disabled by
> local_irq_save()
>   * to avoid races. That way the IDT will always be set back to the
> expected
> @@ -442,6 +508,8 @@ static inline void load_current_idt(void)
>         local_irq_save(flags);
>         if (is_debug_idt_enabled())
>                 load_debug_idt();
> +       if (is_trace_idt_enabled())
> +               load_trace_idt();

This should be:

	else if (is_trace_idt_enabled())

Otherwise, you just totally negated the previous if.

-- Steve

>         else
>                 load_idt((const struct desc_ptr *)&idt_descr);
>         local_irq_restore(flags); 

[Dle-develop] [PATCH v16 4/4] trace, x86: Add irq vector tracepoints

[Seiji A. <sei...@hd...>]

[Purpose of this patch]

As Vaibhav explained in the thread below, tracepoints for irq vectors
are useful.

http://www.spinics.net/lists/mm-commits/msg85707.html

<snip>
The current interrupt traces from irq_handler_entry and irq_handler_exit
provide when an interrupt is handled.  They provide good data about when
the system has switched to kernel space and how it affects the currently
running processes.

There are some IRQ vectors which trigger the system into kernel space,
which are not handled in generic IRQ handlers.  Tracing such events gives
us the information about IRQ interaction with other system events.

The trace also tells where the system is spending its time.  We want to
know which cores are handling interrupts and how they are affecting other
processes in the system.  Also, the trace provides information about when
the cores are idle and which interrupts are changing that state.
<snip>

On the other hand, my usecase is tracing just local timer event and
getting a value of instruction pointer.

I suggested to add an argument local timer event to get instruction pointer before.
But there is another way to get it with external module like systemtap.
So, I don't need to add any argument to irq vector tracepoints now.

[Patch Description]

Vaibhav's patch shared a trace point ,irq_vector_entry/irq_vector_exit, in all events.
But there is an above use case to trace specific irq_vector rather than tracing all events.
In this case, we are concerned about overhead due to unwanted events.

So, add following tracepoints instead of introducing irq_vector_entry/exit.
so that we can enable them independently.
   - local_timer_vector
   - reschedule_vector
   - call_function_vector
   - call_function_single_vector
   - irq_work_entry_vector
   - error_apic_vector
   - thermal_apic_vector
   - threshold_apic_vector
   - spurious_apic_vector
   - x86_platform_ipi_vector

Also, introduce a logic switching IDT at enabling/disabling time so that a time penalty
makes a zero when tracepoints are disabled. Detailed explanations are as follows.
 - Create trace irq handlers with entering_irq()/exiting_irq().
 - Create a new IDT, trace_idt_table, at boot time by adding a logic to
   _set_gate(). It is just a copy of original idt table.
 - Register the new handlers for tracpoints to the new IDT by introducing
   macros to alloc_intr_gate() called at registering time of irq_vector handlers.
 - Add checking, whether irq vector tracing is on/off, into load_current_idt().
   This has to be done below debug checking for these reasons.
   - Switching to debug IDT may be kicked while tracing is enabled.
   - On the other hands, switching to trace IDT is kicked only when debugging
     is disabled.

In addition, the new IDT is created only when CONFIG_TRACING is enabled to avoid being
used for other purposes.

Signed-off-by: Seiji Aguchi <sei...@hd...>
---
 arch/x86/include/asm/desc.h              |   72 ++++++++++++++++++++-
 arch/x86/include/asm/entry_arch.h        |    8 ++-
 arch/x86/include/asm/hw_irq.h            |   17 +++++
 arch/x86/include/asm/mshyperv.h          |    3 +
 arch/x86/include/asm/trace/irq_vectors.h |  104 ++++++++++++++++++++++++++++++
 arch/x86/include/asm/uv/uv_bau.h         |    3 +
 arch/x86/kernel/Makefile                 |    1 +
 arch/x86/kernel/apic/Makefile            |    1 +
 arch/x86/kernel/apic/apic.c              |   42 ++++++++++++
 arch/x86/kernel/cpu/common.c             |    4 +-
 arch/x86/kernel/cpu/mcheck/therm_throt.c |   10 +++
 arch/x86/kernel/cpu/mcheck/threshold.c   |    9 +++
 arch/x86/kernel/entry_32.S               |   12 +++-
 arch/x86/kernel/entry_64.S               |   31 +++++++--
 arch/x86/kernel/head_64.S                |    6 ++
 arch/x86/kernel/irq.c                    |   13 ++++
 arch/x86/kernel/irq_work.c               |   10 +++
 arch/x86/kernel/smp.c                    |   30 +++++++++
 arch/x86/kernel/tracepoint.c             |   57 ++++++++++++++++
 include/xen/events.h                     |    3 +
 20 files changed, 421 insertions(+), 15 deletions(-)
 create mode 100644 arch/x86/include/asm/trace/irq_vectors.h
 create mode 100644 arch/x86/kernel/tracepoint.c

diff --git a/arch/x86/include/asm/desc.h b/arch/x86/include/asm/desc.h
index af290b8..04bf230 100644
--- a/arch/x86/include/asm/desc.h
+++ b/arch/x86/include/asm/desc.h
@@ -320,6 +320,19 @@ static inline void set_nmi_gate(int gate, void *addr)
 }
 #endif
 
+#ifdef CONFIG_TRACING
+extern struct desc_ptr trace_idt_descr;
+extern gate_desc trace_idt_table[];
+static inline void write_trace_idt_entry(int entry, const gate_desc *gate)
+{
+	write_idt_entry(trace_idt_table, entry, gate);
+}
+#else
+static inline void write_trace_idt_entry(int entry, const gate_desc *gate)
+{
+}
+#endif
+
 static inline void _set_gate(int gate, unsigned type, void *addr,
 			     unsigned dpl, unsigned ist, unsigned seg)
 {
@@ -331,6 +344,7 @@ static inline void _set_gate(int gate, unsigned type, void *addr,
 	 * setup time
 	 */
 	write_idt_entry(idt_table, gate, &s);
+	write_trace_idt_entry(gate, &s);
 }
 
 /*
@@ -360,12 +374,39 @@ static inline void alloc_system_vector(int vector)
 	}
 }
 
-static inline void alloc_intr_gate(unsigned int n, void *addr)
+#ifdef CONFIG_TRACING
+static inline void trace_set_intr_gate(unsigned int gate, void *addr)
+{
+	gate_desc s;
+
+	pack_gate(&s, GATE_INTERRUPT, (unsigned long)addr, 0, 0, __KERNEL_CS);
+	write_idt_entry(trace_idt_table, gate, &s);
+}
+
+static inline void __trace_alloc_intr_gate(unsigned int n, void *addr)
+{
+	trace_set_intr_gate(n, addr);
+}
+#else
+static inline void trace_set_intr_gate(unsigned int gate, void *addr)
+{
+}
+
+#define __trace_alloc_intr_gate(n, addr)
+#endif
+
+static inline void __alloc_intr_gate(unsigned int n, void *addr)
 {
-	alloc_system_vector(n);
 	set_intr_gate(n, addr);
 }
 
+#define alloc_intr_gate(n, addr)				\
+	do {							\
+		alloc_system_vector(n);				\
+		__alloc_intr_gate(n, addr);			\
+		__trace_alloc_intr_gate(n, trace_##addr);	\
+	} while (0)
+
 /*
  * This routine sets up an interrupt gate at directory privilege level 3.
  */
@@ -430,6 +471,31 @@ static inline void load_debug_idt(void)
 }
 #endif
 
+#ifdef CONFIG_TRACING
+extern atomic_t trace_idt_ctr;
+static inline bool is_trace_idt_enabled(void)
+{
+	if (atomic_read(&trace_idt_ctr))
+		return true;
+
+	return false;
+}
+
+static inline void load_trace_idt(void)
+{
+	load_idt((const struct desc_ptr *)&trace_idt_descr);
+}
+#else
+static inline bool is_trace_idt_enabled(void)
+{
+	return false;
+}
+
+static inline void load_trace_idt(void)
+{
+}
+#endif
+
 /*
  * the load_current_idt() is called with interrupt disabled by local_irq_save()
  * to avoid races. That way the IDT will always be set back to the expected
@@ -442,6 +508,8 @@ static inline void load_current_idt(void)
 	local_irq_save(flags);
 	if (is_debug_idt_enabled())
 		load_debug_idt();
+	if (is_trace_idt_enabled())
+		load_trace_idt();
 	else
 		load_idt((const struct desc_ptr *)&idt_descr);
 	local_irq_restore(flags);
diff --git a/arch/x86/include/asm/entry_arch.h b/arch/x86/include/asm/entry_arch.h
index 9bd4eca..dc5fa66 100644
--- a/arch/x86/include/asm/entry_arch.h
+++ b/arch/x86/include/asm/entry_arch.h
@@ -13,14 +13,16 @@
 BUILD_INTERRUPT(reschedule_interrupt,RESCHEDULE_VECTOR)
 BUILD_INTERRUPT(call_function_interrupt,CALL_FUNCTION_VECTOR)
 BUILD_INTERRUPT(call_function_single_interrupt,CALL_FUNCTION_SINGLE_VECTOR)
-BUILD_INTERRUPT(irq_move_cleanup_interrupt,IRQ_MOVE_CLEANUP_VECTOR)
-BUILD_INTERRUPT(reboot_interrupt,REBOOT_VECTOR)
+BUILD_INTERRUPT3(irq_move_cleanup_interrupt, IRQ_MOVE_CLEANUP_VECTOR,
+		 smp_irq_move_cleanup_interrupt)
+BUILD_INTERRUPT3(reboot_interrupt, REBOOT_VECTOR, smp_reboot_interrupt)
 #endif
 
 BUILD_INTERRUPT(x86_platform_ipi, X86_PLATFORM_IPI_VECTOR)
 
 #ifdef CONFIG_HAVE_KVM
-BUILD_INTERRUPT(kvm_posted_intr_ipi, POSTED_INTR_VECTOR)
+BUILD_INTERRUPT3(kvm_posted_intr_ipi, POSTED_INTR_VECTOR,
+		 smp_kvm_posted_intr_ipi)
 #endif
 
 /*
diff --git a/arch/x86/include/asm/hw_irq.h b/arch/x86/include/asm/hw_irq.h
index 1da97ef..e4ac559 100644
--- a/arch/x86/include/asm/hw_irq.h
+++ b/arch/x86/include/asm/hw_irq.h
@@ -77,6 +77,23 @@ extern void threshold_interrupt(void);
 extern void call_function_interrupt(void);
 extern void call_function_single_interrupt(void);
 
+#ifdef CONFIG_TRACING
+/* Interrupt handlers registered during init_IRQ */
+extern void trace_apic_timer_interrupt(void);
+extern void trace_x86_platform_ipi(void);
+extern void trace_error_interrupt(void);
+extern void trace_irq_work_interrupt(void);
+extern void trace_spurious_interrupt(void);
+extern void trace_thermal_interrupt(void);
+extern void trace_reschedule_interrupt(void);
+extern void trace_threshold_interrupt(void);
+extern void trace_call_function_interrupt(void);
+extern void trace_call_function_single_interrupt(void);
+#define trace_irq_move_cleanup_interrupt  irq_move_cleanup_interrupt
+#define trace_reboot_interrupt  reboot_interrupt
+#define trace_kvm_posted_intr_ipi kvm_posted_intr_ipi
+#endif /* CONFIG_TRACING */
+
 /* IOAPIC */
 #define IO_APIC_IRQ(x) (((x) >= NR_IRQS_LEGACY) || ((1<<(x)) & io_apic_irqs))
 extern unsigned long io_apic_irqs;
diff --git a/arch/x86/include/asm/mshyperv.h b/arch/x86/include/asm/mshyperv.h
index c2934be..cd9c419 100644
--- a/arch/x86/include/asm/mshyperv.h
+++ b/arch/x86/include/asm/mshyperv.h
@@ -12,6 +12,9 @@ struct ms_hyperv_info {
 extern struct ms_hyperv_info ms_hyperv;
 
 void hyperv_callback_vector(void);
+#ifdef CONFIG_TRACING
+#define trace_hyperv_callback_vector hyperv_callback_vector
+#endif
 void hyperv_vector_handler(struct pt_regs *regs);
 void hv_register_vmbus_handler(int irq, irq_handler_t handler);
 
diff --git a/arch/x86/include/asm/trace/irq_vectors.h b/arch/x86/include/asm/trace/irq_vectors.h
new file mode 100644
index 0000000..2874df2
--- /dev/null
+++ b/arch/x86/include/asm/trace/irq_vectors.h
@@ -0,0 +1,104 @@
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM irq_vectors
+
+#if !defined(_TRACE_IRQ_VECTORS_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_IRQ_VECTORS_H
+
+#include <linux/tracepoint.h>
+
+extern void trace_irq_vector_regfunc(void);
+extern void trace_irq_vector_unregfunc(void);
+
+DECLARE_EVENT_CLASS(x86_irq_vector,
+
+	TP_PROTO(int vector),
+
+	TP_ARGS(vector),
+
+	TP_STRUCT__entry(
+		__field(		int,	vector	)
+	),
+
+	TP_fast_assign(
+		__entry->vector = vector;
+	),
+
+	TP_printk("vector=%d", __entry->vector) );
+
+#define DEFINE_IRQ_VECTOR_EVENT(name)		\
+DEFINE_EVENT_FN(x86_irq_vector, name##_entry,	\
+	TP_PROTO(int vector),			\
+	TP_ARGS(vector),			\
+	trace_irq_vector_regfunc,		\
+	trace_irq_vector_unregfunc);		\
+DEFINE_EVENT_FN(x86_irq_vector, name##_exit,	\
+	TP_PROTO(int vector),			\
+	TP_ARGS(vector),			\
+	trace_irq_vector_regfunc,		\
+	trace_irq_vector_unregfunc);
+
+
+/*
+ * local_timer - called when entering/exiting a local timer interrupt
+ * vector handler
+ */
+DEFINE_IRQ_VECTOR_EVENT(local_timer);
+
+/*
+ * reschedule - called when entering/exiting a reschedule vector handler
+ */
+DEFINE_IRQ_VECTOR_EVENT(reschedule);
+
+/*
+ * spurious_apic - called when entering/exiting a spurious apic vector handler
+ */
+DEFINE_IRQ_VECTOR_EVENT(spurious_apic);
+
+/*
+ * error_apic - called when entering/exiting an error apic vector handler
+ */
+DEFINE_IRQ_VECTOR_EVENT(error_apic);
+
+/*
+ * x86_platform_ipi - called when entering/exiting a x86 platform ipi interrupt
+ * vector handler
+ */
+DEFINE_IRQ_VECTOR_EVENT(x86_platform_ipi);
+
+/*
+ * irq_work - called when entering/exiting a irq work interrupt
+ * vector handler
+ */
+DEFINE_IRQ_VECTOR_EVENT(irq_work);
+
+/*
+ * call_function - called when entering/exiting a call function interrupt
+ * vector handler
+ */
+DEFINE_IRQ_VECTOR_EVENT(call_function);
+
+/*
+ * call_function_single - called when entering/exiting a call function
+ * single interrupt vector handler
+ */
+DEFINE_IRQ_VECTOR_EVENT(call_function_single);
+
+/*
+ * threshold_apic - called when entering/exiting a threshold apic interrupt
+ * vector handler
+ */
+DEFINE_IRQ_VECTOR_EVENT(threshold_apic);
+
+/*
+ * thermal_apic - called when entering/exiting a thermal apic interrupt
+ * vector handler
+ */
+DEFINE_IRQ_VECTOR_EVENT(thermal_apic);
+
+#undef TRACE_INCLUDE_PATH
+#define TRACE_INCLUDE_PATH .
+#define TRACE_INCLUDE_FILE irq_vectors
+#endif /*  _TRACE_IRQ_VECTORS_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>
diff --git a/arch/x86/include/asm/uv/uv_bau.h b/arch/x86/include/asm/uv/uv_bau.h
index a06983c..0b46ef2 100644
--- a/arch/x86/include/asm/uv/uv_bau.h
+++ b/arch/x86/include/asm/uv/uv_bau.h
@@ -731,6 +731,9 @@ static inline void bau_cpubits_clear(struct bau_local_cpumask *dstp, int nbits)
 }
 
 extern void uv_bau_message_intr1(void);
+#ifdef CONFIG_TRACING
+#define trace_uv_bau_message_intr1 uv_bau_message_intr1
+#endif
 extern void uv_bau_timeout_intr1(void);
 
 struct atomic_short {
diff --git a/arch/x86/kernel/Makefile b/arch/x86/kernel/Makefile
index 7bd3bd3..74b3891 100644
--- a/arch/x86/kernel/Makefile
+++ b/arch/x86/kernel/Makefile
@@ -102,6 +102,7 @@ obj-$(CONFIG_OF)			+= devicetree.o
 obj-$(CONFIG_UPROBES)			+= uprobes.o
 
 obj-$(CONFIG_PERF_EVENTS)		+= perf_regs.o
+obj-$(CONFIG_TRACING)			+= tracepoint.o
 
 ###
 # 64 bit specific files
diff --git a/arch/x86/kernel/apic/Makefile b/arch/x86/kernel/apic/Makefile
index 0ae0323..5274c3a 100644
--- a/arch/x86/kernel/apic/Makefile
+++ b/arch/x86/kernel/apic/Makefile
@@ -2,6 +2,7 @@
 # Makefile for local APIC drivers and for the IO-APIC code
 #
 
+CFLAGS_apic.o := -I$(src)/../../include/asm/trace
 obj-$(CONFIG_X86_LOCAL_APIC)	+= apic.o apic_noop.o ipi.o
 obj-y				+= hw_nmi.o
 
diff --git a/arch/x86/kernel/apic/apic.c b/arch/x86/kernel/apic/apic.c
index 59ee76f..61ced40 100644
--- a/arch/x86/kernel/apic/apic.c
+++ b/arch/x86/kernel/apic/apic.c
@@ -55,6 +55,9 @@
 #include <asm/tsc.h>
 #include <asm/hypervisor.h>
 
+#define CREATE_TRACE_POINTS
+#include <asm/trace/irq_vectors.h>
+
 unsigned int num_processors;
 
 unsigned disabled_cpus __cpuinitdata;
@@ -931,6 +934,27 @@ void __irq_entry smp_apic_timer_interrupt(struct pt_regs *regs)
 	set_irq_regs(old_regs);
 }
 
+void __irq_entry smp_trace_apic_timer_interrupt(struct pt_regs *regs)
+{
+	struct pt_regs *old_regs = set_irq_regs(regs);
+
+	/*
+	 * NOTE! We'd better ACK the irq immediately,
+	 * because timer handling can be slow.
+	 *
+	 * update_process_times() expects us to have done irq_enter().
+	 * Besides, if we don't timer interrupts ignore the global
+	 * interrupt lock, which is the WrongThing (tm) to do.
+	 */
+	entering_ack_irq();
+	trace_local_timer_entry(LOCAL_TIMER_VECTOR);
+	local_apic_timer_interrupt();
+	trace_local_timer_exit(LOCAL_TIMER_VECTOR);
+	exiting_irq();
+
+	set_irq_regs(old_regs);
+}
+
 int setup_profiling_timer(unsigned int multiplier)
 {
 	return -EINVAL;
@@ -1931,6 +1955,15 @@ void smp_spurious_interrupt(struct pt_regs *regs)
 	exiting_irq();
 }
 
+void smp_trace_spurious_interrupt(struct pt_regs *regs)
+{
+	entering_irq();
+	trace_spurious_apic_entry(SPURIOUS_APIC_VECTOR);
+	__smp_spurious_interrupt();
+	trace_spurious_apic_exit(SPURIOUS_APIC_VECTOR);
+	exiting_irq();
+}
+
 /*
  * This interrupt should never happen with our APIC/SMP architecture
  */
@@ -1978,6 +2011,15 @@ void smp_error_interrupt(struct pt_regs *regs)
 	exiting_irq();
 }
 
+void smp_trace_error_interrupt(struct pt_regs *regs)
+{
+	entering_irq();
+	trace_error_apic_entry(ERROR_APIC_VECTOR);
+	__smp_error_interrupt(regs);
+	trace_error_apic_exit(ERROR_APIC_VECTOR);
+	exiting_irq();
+}
+
 /**
  * connect_bsp_APIC - attach the APIC to the interrupt system
  */
diff --git a/arch/x86/kernel/cpu/common.c b/arch/x86/kernel/cpu/common.c
index 8f6a0f9..d9c8c09 100644
--- a/arch/x86/kernel/cpu/common.c
+++ b/arch/x86/kernel/cpu/common.c
@@ -1257,7 +1257,7 @@ void __cpuinit cpu_init(void)
 	switch_to_new_gdt(cpu);
 	loadsegment(fs, 0);
 
-	load_idt((const struct desc_ptr *)&idt_descr);
+	load_current_idt();
 
 	memset(me->thread.tls_array, 0, GDT_ENTRY_TLS_ENTRIES * 8);
 	syscall_init();
@@ -1334,7 +1334,7 @@ void __cpuinit cpu_init(void)
 	if (cpu_has_vme || cpu_has_tsc || cpu_has_de)
 		clear_in_cr4(X86_CR4_VME|X86_CR4_PVI|X86_CR4_TSD|X86_CR4_DE);
 
-	load_idt(&idt_descr);
+	load_current_idt();
 	switch_to_new_gdt(cpu);
 
 	/*
diff --git a/arch/x86/kernel/cpu/mcheck/therm_throt.c b/arch/x86/kernel/cpu/mcheck/therm_throt.c
index f6b35f2..2f3a799 100644
--- a/arch/x86/kernel/cpu/mcheck/therm_throt.c
+++ b/arch/x86/kernel/cpu/mcheck/therm_throt.c
@@ -29,6 +29,7 @@
 #include <asm/idle.h>
 #include <asm/mce.h>
 #include <asm/msr.h>
+#include <asm/trace/irq_vectors.h>
 
 /* How long to wait between reporting thermal events */
 #define CHECK_INTERVAL		(300 * HZ)
@@ -391,6 +392,15 @@ asmlinkage void smp_thermal_interrupt(struct pt_regs *regs)
 	exiting_ack_irq();
 }
 
+asmlinkage void smp_trace_thermal_interrupt(struct pt_regs *regs)
+{
+	entering_irq();
+	trace_thermal_apic_entry(THERMAL_APIC_VECTOR);
+	__smp_thermal_interrupt();
+	trace_thermal_apic_exit(THERMAL_APIC_VECTOR);
+	exiting_ack_irq();
+}
+
 /* Thermal monitoring depends on APIC, ACPI and clock modulation */
 static int intel_thermal_supported(struct cpuinfo_x86 *c)
 {
diff --git a/arch/x86/kernel/cpu/mcheck/threshold.c b/arch/x86/kernel/cpu/mcheck/threshold.c
index f20988a..fe6b1c8 100644
--- a/arch/x86/kernel/cpu/mcheck/threshold.c
+++ b/arch/x86/kernel/cpu/mcheck/threshold.c
@@ -8,6 +8,7 @@
 #include <asm/apic.h>
 #include <asm/idle.h>
 #include <asm/mce.h>
+#include <asm/trace/irq_vectors.h>
 
 static void default_threshold_interrupt(void)
 {
@@ -30,3 +31,11 @@ asmlinkage void smp_threshold_interrupt(void)
 	exiting_ack_irq();
 }
 
+asmlinkage void smp_trace_threshold_interrupt(void)
+{
+	entering_irq();
+	trace_threshold_apic_entry(THRESHOLD_APIC_VECTOR);
+	__smp_threshold_interrupt();
+	trace_threshold_apic_exit(THRESHOLD_APIC_VECTOR);
+	exiting_ack_irq();
+}
diff --git a/arch/x86/kernel/entry_32.S b/arch/x86/kernel/entry_32.S
index 8f3e2de..2cfbc3a 100644
--- a/arch/x86/kernel/entry_32.S
+++ b/arch/x86/kernel/entry_32.S
@@ -801,7 +801,17 @@ ENTRY(name)				\
 	CFI_ENDPROC;			\
 ENDPROC(name)
 
-#define BUILD_INTERRUPT(name, nr)	BUILD_INTERRUPT3(name, nr, smp_##name)
+
+#ifdef CONFIG_TRACING
+#define TRACE_BUILD_INTERRUPT(name, nr)		\
+	BUILD_INTERRUPT3(trace_##name, nr, smp_trace_##name)
+#else
+#define TRACE_BUILD_INTERRUPT(name, nr)
+#endif
+
+#define BUILD_INTERRUPT(name, nr) \
+	BUILD_INTERRUPT3(name, nr, smp_##name); \
+	TRACE_BUILD_INTERRUPT(name, nr)
 
 /* The include is where all of the SMP etc. interrupts come from */
 #include <asm/entry_arch.h>
diff --git a/arch/x86/kernel/entry_64.S b/arch/x86/kernel/entry_64.S
index 7272089..11eef43 100644
--- a/arch/x86/kernel/entry_64.S
+++ b/arch/x86/kernel/entry_64.S
@@ -1138,7 +1138,7 @@ END(common_interrupt)
 /*
  * APIC interrupts.
  */
-.macro apicinterrupt num sym do_sym
+.macro apicinterrupt3 num sym do_sym
 ENTRY(\sym)
 	INTR_FRAME
 	ASM_CLAC
@@ -1150,15 +1150,32 @@ ENTRY(\sym)
 END(\sym)
 .endm
 
+#ifdef CONFIG_TRACING
+#define trace(sym) trace_##sym
+#define smp_trace(sym) smp_trace_##sym
+
+.macro trace_apicinterrupt num sym
+apicinterrupt3 \num trace(\sym) smp_trace(\sym)
+.endm
+#else
+.macro trace_apicinterrupt num sym do_sym
+.endm
+#endif
+
+.macro apicinterrupt num sym do_sym
+apicinterrupt3 \num \sym \do_sym
+trace_apicinterrupt \num \sym
+.endm
+
 #ifdef CONFIG_SMP
-apicinterrupt IRQ_MOVE_CLEANUP_VECTOR \
+apicinterrupt3 IRQ_MOVE_CLEANUP_VECTOR \
 	irq_move_cleanup_interrupt smp_irq_move_cleanup_interrupt
-apicinterrupt REBOOT_VECTOR \
+apicinterrupt3 REBOOT_VECTOR \
 	reboot_interrupt smp_reboot_interrupt
 #endif
 
 #ifdef CONFIG_X86_UV
-apicinterrupt UV_BAU_MESSAGE \
+apicinterrupt3 UV_BAU_MESSAGE \
 	uv_bau_message_intr1 uv_bau_message_interrupt
 #endif
 apicinterrupt LOCAL_TIMER_VECTOR \
@@ -1167,7 +1184,7 @@ apicinterrupt X86_PLATFORM_IPI_VECTOR \
 	x86_platform_ipi smp_x86_platform_ipi
 
 #ifdef CONFIG_HAVE_KVM
-apicinterrupt POSTED_INTR_VECTOR \
+apicinterrupt3 POSTED_INTR_VECTOR \
 	kvm_posted_intr_ipi smp_kvm_posted_intr_ipi
 #endif
 
@@ -1451,13 +1468,13 @@ ENTRY(xen_failsafe_callback)
 	CFI_ENDPROC
 END(xen_failsafe_callback)
 
-apicinterrupt HYPERVISOR_CALLBACK_VECTOR \
+apicinterrupt3 HYPERVISOR_CALLBACK_VECTOR \
 	xen_hvm_callback_vector xen_evtchn_do_upcall
 
 #endif /* CONFIG_XEN */
 
 #if IS_ENABLED(CONFIG_HYPERV)
-apicinterrupt HYPERVISOR_CALLBACK_VECTOR \
+apicinterrupt3 HYPERVISOR_CALLBACK_VECTOR \
 	hyperv_callback_vector hyperv_vector_handler
 #endif /* CONFIG_HYPERV */
 
diff --git a/arch/x86/kernel/head_64.S b/arch/x86/kernel/head_64.S
index 84fb779..5e4d8a8 100644
--- a/arch/x86/kernel/head_64.S
+++ b/arch/x86/kernel/head_64.S
@@ -521,6 +521,12 @@ ENTRY(idt_table)
 ENTRY(debug_idt_table)
 	.skip IDT_ENTRIES * 16
 
+#ifdef CONFIG_TRACING
+	.align L1_CACHE_BYTES
+ENTRY(trace_idt_table)
+	.skip IDT_ENTRIES * 16
+#endif
+
 	__PAGE_ALIGNED_BSS
 NEXT_PAGE(empty_zero_page)
 	.skip PAGE_SIZE
diff --git a/arch/x86/kernel/irq.c b/arch/x86/kernel/irq.c
index e3b8df1..06af119 100644
--- a/arch/x86/kernel/irq.c
+++ b/arch/x86/kernel/irq.c
@@ -17,6 +17,7 @@
 #include <asm/idle.h>
 #include <asm/mce.h>
 #include <asm/hw_irq.h>
+#include <asm/trace/irq_vectors.h>
 
 atomic_t irq_err_count;
 
@@ -244,6 +245,18 @@ void smp_kvm_posted_intr_ipi(struct pt_regs *regs)
 }
 #endif
 
+void smp_trace_x86_platform_ipi(struct pt_regs *regs)
+{
+	struct pt_regs *old_regs = set_irq_regs(regs);
+
+	entering_ack_irq();
+	trace_x86_platform_ipi_entry(X86_PLATFORM_IPI_VECTOR);
+	__smp_x86_platform_ipi();
+	trace_x86_platform_ipi_exit(X86_PLATFORM_IPI_VECTOR);
+	exiting_irq();
+	set_irq_regs(old_regs);
+}
+
 EXPORT_SYMBOL_GPL(vector_used_by_percpu_irq);
 
 #ifdef CONFIG_HOTPLUG_CPU
diff --git a/arch/x86/kernel/irq_work.c b/arch/x86/kernel/irq_work.c
index 074d46f..636a55e 100644
--- a/arch/x86/kernel/irq_work.c
+++ b/arch/x86/kernel/irq_work.c
@@ -8,6 +8,7 @@
 #include <linux/irq_work.h>
 #include <linux/hardirq.h>
 #include <asm/apic.h>
+#include <asm/trace/irq_vectors.h>
 
 static inline void irq_work_entering_irq(void)
 {
@@ -28,6 +29,15 @@ void smp_irq_work_interrupt(struct pt_regs *regs)
 	exiting_irq();
 }
 
+void smp_trace_irq_work_interrupt(struct pt_regs *regs)
+{
+	irq_work_entering_irq();
+	trace_irq_work_entry(IRQ_WORK_VECTOR);
+	__smp_irq_work_interrupt();
+	trace_irq_work_exit(IRQ_WORK_VECTOR);
+	exiting_irq();
+}
+
 void arch_irq_work_raise(void)
 {
 #ifdef CONFIG_X86_LOCAL_APIC
diff --git a/arch/x86/kernel/smp.c b/arch/x86/kernel/smp.c
index d858375..f4fe0b8 100644
--- a/arch/x86/kernel/smp.c
+++ b/arch/x86/kernel/smp.c
@@ -30,6 +30,7 @@
 #include <asm/proto.h>
 #include <asm/apic.h>
 #include <asm/nmi.h>
+#include <asm/trace/irq_vectors.h>
 /*
  *	Some notes on x86 processor bugs affecting SMP operation:
  *
@@ -264,6 +265,17 @@ void smp_reschedule_interrupt(struct pt_regs *regs)
 	 */
 }
 
+void smp_trace_reschedule_interrupt(struct pt_regs *regs)
+{
+	ack_APIC_irq();
+	trace_reschedule_entry(RESCHEDULE_VECTOR);
+	__smp_reschedule_interrupt();
+	trace_reschedule_exit(RESCHEDULE_VECTOR);
+	/*
+	 * KVM uses this interrupt to force a cpu out of guest mode
+	 */
+}
+
 static inline void call_function_entering_irq(void)
 {
 	ack_APIC_irq();
@@ -283,6 +295,15 @@ void smp_call_function_interrupt(struct pt_regs *regs)
 	exiting_irq();
 }
 
+void smp_trace_call_function_interrupt(struct pt_regs *regs)
+{
+	call_function_entering_irq();
+	trace_call_function_entry(CALL_FUNCTION_VECTOR);
+	__smp_call_function_interrupt();
+	trace_call_function_exit(CALL_FUNCTION_VECTOR);
+	exiting_irq();
+}
+
 static inline void __smp_call_function_single_interrupt(void)
 {
 	generic_smp_call_function_single_interrupt();
@@ -296,6 +317,15 @@ void smp_call_function_single_interrupt(struct pt_regs *regs)
 	exiting_irq();
 }
 
+void smp_trace_call_function_single_interrupt(struct pt_regs *regs)
+{
+	call_function_entering_irq();
+	trace_call_function_single_entry(CALL_FUNCTION_SINGLE_VECTOR);
+	__smp_call_function_single_interrupt();
+	trace_call_function_single_exit(CALL_FUNCTION_SINGLE_VECTOR);
+	exiting_irq();
+}
+
 static int __init nonmi_ipi_setup(char *str)
 {
 	smp_no_nmi_ipi = true;
diff --git a/arch/x86/kernel/tracepoint.c b/arch/x86/kernel/tracepoint.c
new file mode 100644
index 0000000..1423efe
--- /dev/null
+++ b/arch/x86/kernel/tracepoint.c
@@ -0,0 +1,57 @@
+/*
+ * Code for supporting irq vector tracepoints.
+ *
+ * Copyright (C) 2013 Seiji Aguchi <sei...@hd...>
+ *
+ */
+#include <asm/hw_irq.h>
+#include <asm/desc.h>
+#include <linux/atomic.h>
+
+atomic_t trace_idt_ctr = ATOMIC_INIT(0);
+struct desc_ptr trace_idt_descr = { NR_VECTORS * 16 - 1,
+				(unsigned long) trace_idt_table };
+
+#ifndef CONFIG_X86_64
+gate_desc trace_idt_table[NR_VECTORS] __page_aligned_data
+					= { { { { 0, 0 } } }, };
+#endif
+
+static int trace_irq_vector_refcount;
+static DEFINE_MUTEX(irq_vector_mutex);
+
+static void set_trace_idt_ctr(int val)
+{
+	atomic_set(&trace_idt_ctr, val);
+	/* Ensure the trace_idt_ctr is set before sending IPI */
+	wmb();
+}
+
+static void switch_idt(void *arg)
+{
+	load_current_idt();
+}
+
+void trace_irq_vector_regfunc(void)
+{
+	mutex_lock(&irq_vector_mutex);
+	if (!trace_irq_vector_refcount) {
+		set_trace_idt_ctr(1);
+		smp_call_function(switch_idt, NULL, 0);
+		switch_idt(NULL);
+	}
+	trace_irq_vector_refcount++;
+	mutex_unlock(&irq_vector_mutex);
+}
+
+void trace_irq_vector_unregfunc(void)
+{
+	mutex_lock(&irq_vector_mutex);
+	trace_irq_vector_refcount--;
+	if (!trace_irq_vector_refcount) {
+		set_trace_idt_ctr(0);
+		smp_call_function(switch_idt, NULL, 0);
+		switch_idt(NULL);
+	}
+	mutex_unlock(&irq_vector_mutex);
+}
diff --git a/include/xen/events.h b/include/xen/events.h
index b2b27c6..c9ea10e 100644
--- a/include/xen/events.h
+++ b/include/xen/events.h
@@ -76,6 +76,9 @@ unsigned irq_from_evtchn(unsigned int evtchn);
 
 /* Xen HVM evtchn vector callback */
 void xen_hvm_callback_vector(void);
+#ifdef CONFIG_TRACING
+#define trace_xen_hvm_callback_vector xen_hvm_callback_vector
+#endif
 extern int xen_have_vector_callback;
 int xen_set_callback_via(uint64_t via);
 void xen_evtchn_do_upcall(struct pt_regs *regs);
-- 
1.7.1

[Dle-develop] [PATCH v16 3/4] x86: Rename variables for debugging

[Seiji A. <sei...@hd...>]

Rename variables for debugging to describe meaning of them precisely.

Also, introduce a generic way to switch IDT by checking a current state,
debug on/off.

Signed-off-by: Seiji Aguchi <sei...@hd...>
---
 arch/x86/include/asm/desc.h  |   47 +++++++++++++++++++++++++++++++++++++++--
 arch/x86/kernel/cpu/common.c |   16 +++++++-------
 arch/x86/kernel/head_64.S    |    2 +-
 arch/x86/kernel/traps.c      |    2 +-
 4 files changed, 54 insertions(+), 13 deletions(-)

diff --git a/arch/x86/include/asm/desc.h b/arch/x86/include/asm/desc.h
index 8bf1c06..af290b8 100644
--- a/arch/x86/include/asm/desc.h
+++ b/arch/x86/include/asm/desc.h
@@ -36,8 +36,8 @@ static inline void fill_ldt(struct desc_struct *desc, const struct user_desc *in
 
 extern struct desc_ptr idt_descr;
 extern gate_desc idt_table[];
-extern struct desc_ptr nmi_idt_descr;
-extern gate_desc nmi_idt_table[];
+extern struct desc_ptr debug_idt_descr;
+extern gate_desc debug_idt_table[];
 
 struct gdt_page {
 	struct desc_struct gdt[GDT_ENTRIES];
@@ -316,7 +316,7 @@ static inline void set_nmi_gate(int gate, void *addr)
 	gate_desc s;
 
 	pack_gate(&s, GATE_INTERRUPT, (unsigned long)addr, 0, 0, __KERNEL_CS);
-	write_idt_entry(nmi_idt_table, gate, &s);
+	write_idt_entry(debug_idt_table, gate, &s);
 }
 #endif
 
@@ -405,4 +405,45 @@ static inline void set_system_intr_gate_ist(int n, void *addr, unsigned ist)
 	_set_gate(n, GATE_INTERRUPT, addr, 0x3, ist, __KERNEL_CS);
 }
 
+#ifdef CONFIG_X86_64
+DECLARE_PER_CPU(u32, debug_idt_ctr);
+static inline bool is_debug_idt_enabled(void)
+{
+	if (this_cpu_read(debug_idt_ctr))
+		return true;
+
+	return false;
+}
+
+static inline void load_debug_idt(void)
+{
+	load_idt((const struct desc_ptr *)&debug_idt_descr);
+}
+#else
+static inline bool is_debug_idt_enabled(void)
+{
+	return false;
+}
+
+static inline void load_debug_idt(void)
+{
+}
+#endif
+
+/*
+ * the load_current_idt() is called with interrupt disabled by local_irq_save()
+ * to avoid races. That way the IDT will always be set back to the expected
+ * descriptor.
+ */
+static inline void load_current_idt(void)
+{
+	unsigned long flags;
+
+	local_irq_save(flags);
+	if (is_debug_idt_enabled())
+		load_debug_idt();
+	else
+		load_idt((const struct desc_ptr *)&idt_descr);
+	local_irq_restore(flags);
+}
 #endif /* _ASM_X86_DESC_H */
diff --git a/arch/x86/kernel/cpu/common.c b/arch/x86/kernel/cpu/common.c
index 22018f7..8f6a0f9 100644
--- a/arch/x86/kernel/cpu/common.c
+++ b/arch/x86/kernel/cpu/common.c
@@ -1071,8 +1071,8 @@ __setup("clearcpuid=", setup_disablecpuid);
 
 #ifdef CONFIG_X86_64
 struct desc_ptr idt_descr = { NR_VECTORS * 16 - 1, (unsigned long) idt_table };
-struct desc_ptr nmi_idt_descr = { NR_VECTORS * 16 - 1,
-				    (unsigned long) nmi_idt_table };
+struct desc_ptr debug_idt_descr = { NR_VECTORS * 16 - 1,
+				    (unsigned long) debug_idt_table };
 
 DEFINE_PER_CPU_FIRST(union irq_stack_union,
 		     irq_stack_union) __aligned(PAGE_SIZE);
@@ -1148,20 +1148,20 @@ int is_debug_stack(unsigned long addr)
 		 addr > (__get_cpu_var(debug_stack_addr) - DEBUG_STKSZ));
 }
 
-static DEFINE_PER_CPU(u32, debug_stack_use_ctr);
+DEFINE_PER_CPU(u32, debug_idt_ctr);
 
 void debug_stack_set_zero(void)
 {
-	this_cpu_inc(debug_stack_use_ctr);
-	load_idt((const struct desc_ptr *)&nmi_idt_descr);
+	this_cpu_inc(debug_idt_ctr);
+	load_current_idt();
 }
 
 void debug_stack_reset(void)
 {
-	if (WARN_ON(!this_cpu_read(debug_stack_use_ctr)))
+	if (WARN_ON(!this_cpu_read(debug_idt_ctr)))
 		return;
-	if (this_cpu_dec_return(debug_stack_use_ctr) == 0)
-		load_idt((const struct desc_ptr *)&idt_descr);
+	if (this_cpu_dec_return(debug_idt_ctr) == 0)
+		load_current_idt();
 }
 
 #else	/* CONFIG_X86_64 */
diff --git a/arch/x86/kernel/head_64.S b/arch/x86/kernel/head_64.S
index 321d65e..84fb779 100644
--- a/arch/x86/kernel/head_64.S
+++ b/arch/x86/kernel/head_64.S
@@ -518,7 +518,7 @@ ENTRY(idt_table)
 	.skip IDT_ENTRIES * 16
 
 	.align L1_CACHE_BYTES
-ENTRY(nmi_idt_table)
+ENTRY(debug_idt_table)
 	.skip IDT_ENTRIES * 16
 
 	__PAGE_ALIGNED_BSS
diff --git a/arch/x86/kernel/traps.c b/arch/x86/kernel/traps.c
index 772e2a8..d27182d 100644
--- a/arch/x86/kernel/traps.c
+++ b/arch/x86/kernel/traps.c
@@ -785,7 +785,7 @@ void __init trap_init(void)
 	x86_init.irqs.trap_init();
 
 #ifdef CONFIG_X86_64
-	memcpy(&nmi_idt_table, &idt_table, IDT_ENTRIES * 16);
+	memcpy(&debug_idt_table, &idt_table, IDT_ENTRIES * 16);
 	set_nmi_gate(X86_TRAP_DB, &debug);
 	set_nmi_gate(X86_TRAP_BP, &int3);
 #endif
-- 
1.7.1