Re: [PATCH v2 6/7] pstore: Add support to store timestamp counter in ftrace records

[Kees Cook <keescook@chromium.org>]

On Thu, Nov 10, 2016 at 4:21 PM, Joel Fernandes <joelaf@google.com> wrote:
> On Thu, Nov 10, 2016 at 4:15 PM, Kees Cook <keescook@chromium.org> wrote:
>> On Thu, Oct 20, 2016 at 12:34 AM, Joel Fernandes <joelaf@google.com> wrote:
>>> In preparation for merging the per CPU buffers into one buffer when we retrieve
>>> the pstore ftrace data, we store the timestamp as a counter in the ftrace
>>> pstore record.  We store the CPU number as well if !PSTORE_CPU_IN_IP, in this
>>> case we shift the counter and may lose ordering there but we preserve the same
>>> record size. The timestamp counter is also racy, and not doing any locking or
>>> synchronization here results in the benefit of lower overhead. Since we don't
>>> care much here for exact ordering of function traces across CPUs, we don't
>>> synchronize and may lose some counter updates but I'm ok with that.
>>>
>>> Using trace_clock() results in much lower performance so avoid using it since
>>> we don't want accuracy in timestamp and need a rough ordering to perform merge.
>>>
>>> Signed-off-by: Joel Fernandes <joelaf@google.com>
>>> ---
>>>  fs/pstore/ftrace.c     |  3 +++
>>>  fs/pstore/inode.c      |  7 ++---
>>>  fs/pstore/internal.h   | 34 -------------------------
>>>  include/linux/pstore.h | 69 ++++++++++++++++++++++++++++++++++++++++++++++++++
>>>  4 files changed, 76 insertions(+), 37 deletions(-)
>>>
>>> diff --git a/fs/pstore/ftrace.c b/fs/pstore/ftrace.c
>>> index d488770..1c6cf86 100644
>>> --- a/fs/pstore/ftrace.c
>>> +++ b/fs/pstore/ftrace.c
>>> @@ -27,6 +27,8 @@
>>>  #include <asm/barrier.h>
>>>  #include "internal.h"
>>>
>>> +static u64 pstore_ftrace_stamp;
>>
>> I think the race described in the commit message deserves a comment here.
>
> Sure, I can add that.
>
>>> +
>>>  static void notrace pstore_ftrace_call(unsigned long ip,
>>>                                        unsigned long parent_ip,
>>>                                        struct ftrace_ops *op,
>>> @@ -42,6 +44,7 @@ static void notrace pstore_ftrace_call(unsigned long ip,
>>>
>>>         rec.ip = ip;
>>>         rec.parent_ip = parent_ip;
>>> +       pstore_ftrace_write_timestamp(&rec, pstore_ftrace_stamp++);
>>>         pstore_ftrace_encode_cpu(&rec, raw_smp_processor_id());
>>>         psinfo->write_buf(PSTORE_TYPE_FTRACE, 0, NULL, 0, (void *)&rec,
>>>                           0, sizeof(rec), psinfo);
>>> diff --git a/fs/pstore/inode.c b/fs/pstore/inode.c
>>> index ec9ddef..fcc5d1a 100644
>>> --- a/fs/pstore/inode.c
>>> +++ b/fs/pstore/inode.c
>>> @@ -107,9 +107,10 @@ static int pstore_ftrace_seq_show(struct seq_file *s, void *v)
>>>         struct pstore_ftrace_seq_data *data = v;
>>>         struct pstore_ftrace_record *rec = (void *)(ps->data + data->off);
>>>
>>> -       seq_printf(s, "%d %08lx  %08lx  %pf <- %pF\n",
>>> -               pstore_ftrace_decode_cpu(rec), rec->ip, rec->parent_ip,
>>> -               (void *)rec->ip, (void *)rec->parent_ip);
>>> +       seq_printf(s, "CPU:%d ts:%llu %08lx  %08lx  %pf <- %pF\n",
>>> +                  pstore_ftrace_decode_cpu(rec), pstore_ftrace_read_timestamp(rec),
>>> +                  rec->ip, rec->parent_ip, (void *)rec->ip,
>>> +                  (void *)rec->parent_ip);
>>>
>>>         return 0;
>>>  }
>>> diff --git a/fs/pstore/internal.h b/fs/pstore/internal.h
>>> index e38a22b..da416e6 100644
>>> --- a/fs/pstore/internal.h
>>> +++ b/fs/pstore/internal.h
>>> @@ -5,40 +5,6 @@
>>>  #include <linux/time.h>
>>>  #include <linux/pstore.h>
>>>
>>> -#if NR_CPUS <= 2 && defined(CONFIG_ARM_THUMB)
>>> -#define PSTORE_CPU_IN_IP 0x1
>>> -#elif NR_CPUS <= 4 && defined(CONFIG_ARM)
>>> -#define PSTORE_CPU_IN_IP 0x3
>>> -#endif
>>> -
>>> -struct pstore_ftrace_record {
>>> -       unsigned long ip;
>>> -       unsigned long parent_ip;
>>> -#ifndef PSTORE_CPU_IN_IP
>>> -       unsigned int cpu;
>>> -#endif
>>> -};
>>> -
>>> -static inline void
>>> -pstore_ftrace_encode_cpu(struct pstore_ftrace_record *rec, unsigned int cpu)
>>> -{
>>> -#ifndef PSTORE_CPU_IN_IP
>>> -       rec->cpu = cpu;
>>> -#else
>>> -       rec->ip |= cpu;
>>> -#endif
>>> -}
>>> -
>>> -static inline unsigned int
>>> -pstore_ftrace_decode_cpu(struct pstore_ftrace_record *rec)
>>> -{
>>> -#ifndef PSTORE_CPU_IN_IP
>>> -       return rec->cpu;
>>> -#else
>>> -       return rec->ip & PSTORE_CPU_IN_IP;
>>> -#endif
>>> -}
>>> -
>>>  #ifdef CONFIG_PSTORE_FTRACE
>>>  extern void pstore_register_ftrace(void);
>>>  extern void pstore_unregister_ftrace(void);
>>> diff --git a/include/linux/pstore.h b/include/linux/pstore.h
>>> index 92013cc..4e7fc3c 100644
>>> --- a/include/linux/pstore.h
>>> +++ b/include/linux/pstore.h
>>> @@ -89,4 +89,73 @@ extern int pstore_register(struct pstore_info *);
>>>  extern void pstore_unregister(struct pstore_info *);
>>>  extern bool pstore_cannot_block_path(enum kmsg_dump_reason reason);
>>>
>>> +struct pstore_ftrace_record {
>>> +       unsigned long ip;
>>> +       unsigned long parent_ip;
>>> +       u64 ts;
>>> +};
>>> +
>>> +/*
>>> + * ftrace related stuff: Both backends and frontends need these so expose them
>>> + */
>>> +
>>> +#if NR_CPUS <= 2 && defined(CONFIG_ARM_THUMB)
>>> +#define PSTORE_CPU_IN_IP 0x1
>>> +#elif NR_CPUS <= 4 && defined(CONFIG_ARM)
>>> +#define PSTORE_CPU_IN_IP 0x3
>>> +#endif
>>> +
>>> +#define TS_CPU_SHIFT 8
>>> +#define TS_CPU_MASK (BIT(TS_CPU_SHIFT) - 1)
>>> +
>>> +/*
>>> + * If CPU number can be stored in IP, store it there
>>> + * else store it in the time stamp.
>>> + */
>>> +#ifdef PSTORE_CPU_IN_IP
>>> +static inline void
>>> +pstore_ftrace_encode_cpu(struct pstore_ftrace_record *rec, unsigned int cpu)
>>> +{
>>> +       rec->ip |= cpu;
>>> +}
>>> +
>>> +static inline unsigned int
>>> +pstore_ftrace_decode_cpu(struct pstore_ftrace_record *rec)
>>> +{
>>> +       return rec->ip & PSTORE_CPU_IN_IP;
>>> +}
>>> +
>>> +static inline u64 pstore_ftrace_read_timestamp(struct pstore_ftrace_record *rec)
>>> +{
>>> +       return rec->ts;
>>> +}
>>> +
>>> +static inline void pstore_ftrace_write_timestamp(struct pstore_ftrace_record *rec, u64 val)
>>> +{
>>> +       rec->ts = val;
>>> +}
>>> +#else
>>> +static inline void
>>> +pstore_ftrace_encode_cpu(struct pstore_ftrace_record *rec, unsigned int cpu)
>>> +{
>>> +       rec->ts &= ~(TS_CPU_MASK);
>>> +       rec->ts |= cpu;
>>> +}
>>> +
>>> +static inline unsigned int
>>> +pstore_ftrace_decode_cpu(struct pstore_ftrace_record *rec)
>>> +{
>>> +       return rec->ts & TS_CPU_MASK;
>>> +}
>>> +
>>> +static inline u64 pstore_ftrace_read_timestamp(struct pstore_ftrace_record *rec)
>>> +{
>>> +       return rec->ts >> TS_CPU_SHIFT;
>>> +}
>>> +
>>> +static inline void pstore_ftrace_write_timestamp(struct pstore_ftrace_record *rec, u64 val)
>>> +{
>>> +       rec->ts = (rec->ts & TS_CPU_MASK) | (val << TS_CPU_SHIFT);
>>> +}
>>> +#endif
>>>  #endif /*_LINUX_PSTORE_H*/
>>> --
>>> 2.7.4
>>>
>>
>> Should these ftrace helpers live somewhere else? It seems really
>> specific to ftrace, not pstore?
>>
>> -Kees
>>
>
> Actually the time stamp and CPU information is not specific to low
> level ftrace hooks. Ftrace just provides the hooks into the function
> calls, its upto the user to store this information how they want. So
> the pstore ftrace helpers should be included in the pstore header IMO.

Okay, gotcha. Thanks!

-Kees

-- 
Kees Cook
Nexus Security