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

[Joel Fernandes]

On Thu, Nov 10, 2016 at 4:15 PM, Kees Cook <keescook@xxxxxxxxxxxx> wrote:
> On Thu, Oct 20, 2016 at 12:34 AM, Joel Fernandes <joelaf@xxxxxxxxxx> 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@xxxxxxxxxx>
>> ---
>>  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.

Thanks,

Joel