Re: [PATCH v2] ring-buffer: Have nested events still record running time stamp

From: kernel test robot
Date: Fri Jun 26 2020 - 00:29:01 EST

Hi Steven,

Thank you for the patch! Perhaps something to improve:

[auto build test WARNING on tip/perf/core]
[also build test WARNING on linux/master linus/master v5.8-rc2 next-20200625]
[If your patch is applied to the wrong git tree, kindly drop us a note.
And when submitting patch, we suggest to use as documented in
https://git-scm.com/docs/git-format-patch]

url: https://github.com/0day-ci/linux/commits/Steven-Rostedt/ring-buffer-Have-nested-events-still-record-running-time-stamp/20200626-105715
base: https://git.kernel.org/pub/scm/linux/kernel/git/tip/tip.git bb42b3d39781d7fcd3be7f9f9bf11b6661b5fdf1
config: mips-allyesconfig (attached as .config)
compiler: mips-linux-gcc (GCC) 9.3.0
reproduce (this is a W=1 build):
wget https://raw.githubusercontent.com/intel/lkp-tests/master/sbin/make.cross -O ~/bin/make.cross
chmod +x ~/bin/make.cross
# save the attached .config to linux build tree
COMPILER_INSTALL_PATH=$HOME/0day COMPILER=gcc-9.3.0 make.cross ARCH=mips

If you fix the issue, kindly add following tag as appropriate
Reported-by: kernel test robot <lkp@xxxxxxxxx>

All warnings (new ones prefixed by >>):

kernel/trace/ring_buffer.c: In function '__rb_reserve_next':
kernel/trace/ring_buffer.c:2911:6: warning: unused variable 'delta' [-Wunused-variable]
2911 | u64 delta, before, after;
| ^~~~~
>> kernel/trace/ring_buffer.c:2910:32: warning: variable 'next' set but not used [-Wunused-but-set-variable]
2910 | unsigned long tail, write, w, next;
| ^~~~

vim +/next +2910 kernel/trace/ring_buffer.c

2903
2904 static struct ring_buffer_event *
2905 __rb_reserve_next(struct ring_buffer_per_cpu *cpu_buffer,
2906 struct rb_event_info *info)
2907 {
2908 struct ring_buffer_event *event;
2909 struct buffer_page *tail_page;
> 2910 unsigned long tail, write, w, next;
2911 u64 delta, before, after;
2912 bool abs = false;
2913
2914 /* Don't let the compiler play games with cpu_buffer->tail_page */
2915 tail_page = info->tail_page = READ_ONCE(cpu_buffer->tail_page);
2916
2917 /*A*/ w = local_read(&tail_page->write) & RB_WRITE_MASK;
2918 barrier();
2919 before = local64_read(&cpu_buffer->before_stamp);
2920 after = local64_read(&cpu_buffer->write_stamp);
2921 barrier();
2922 info->ts = rb_time_stamp(cpu_buffer->buffer);
2923
2924 if (ring_buffer_time_stamp_abs(cpu_buffer->buffer)) {
2925 info->delta = info->ts;
2926 abs = true;
2927 } else {
2928 info->delta = info->ts - after;
2929 }
2930
2931 if (unlikely(test_time_stamp(info->delta)))
2932 rb_handle_timestamp(cpu_buffer, info);
2933
2934 /*
2935 * If interrupting an event time update, we may need an absolute timestamp.
2936 * Don't bother if this is the start of a new page (w == 0).
2937 */
2938 if (unlikely(before != after && w))
2939 info->add_timestamp = RB_ADD_STAMP_FORCE;
2940 /*
2941 * If the time delta since the last event is too big to
2942 * hold in the time field of the event, then we append a
2943 * TIME EXTEND event ahead of the data event.
2944 */
2945 if (unlikely(info->add_timestamp))
2946 info->length += RB_LEN_TIME_EXTEND;
2947
2948 next = READ_ONCE(cpu_buffer->next_write);
2949 WRITE_ONCE(cpu_buffer->next_write, w + info->length);
2950
2951 /*B*/ local64_set(&cpu_buffer->before_stamp, info->ts);
2952
2953 /*C*/ write = local_add_return(info->length, &tail_page->write);
2954
2955 /* set write to only the index of the write */
2956 write &= RB_WRITE_MASK;
2957
2958 tail = write - info->length;
2959
2960 /* See if we shot pass the end of this buffer page */
2961 if (unlikely(write > BUF_PAGE_SIZE)) {
2962 if (tail != w) {
2963 /* before and after may now different, fix it up*/
2964 before = local64_read(&cpu_buffer->before_stamp);
2965 after = local64_read(&cpu_buffer->write_stamp);
2966 if (before != after)
2967 (void)local64_cmpxchg(&cpu_buffer->before_stamp, before, after);
2968 }
2969 return rb_move_tail(cpu_buffer, tail, info);
2970 }
2971
2972 if (likely(tail == w)) {
2973 u64 save_before;
2974
2975 /* Nothing interrupted us between A and C */
2976 /*D*/ local64_set(&cpu_buffer->write_stamp, info->ts);
2977 barrier();
2978 /*E*/ save_before = local64_read(&cpu_buffer->before_stamp);
2979 if (likely(info->add_timestamp != RB_ADD_STAMP_FORCE))
2980 /* This did not interrupt any time update */
2981 info->delta = info->ts - after;
2982 else
2983 /* Just use full timestamp for inerrupting event */
2984 info->delta = info->ts;
2985 barrier();
2986 if (unlikely(info->ts != save_before)) {
2987 /* SLOW PATH - Interrupted between C and E */
2988
2989 after = local64_read(&cpu_buffer->write_stamp);
2990 /* Write stamp must only go forward */
2991 if (save_before > after) {
2992 /*
2993 * We do not care about the result, only that
2994 * it gets updated atomically.
2995 */
2996 (void)local64_cmpxchg(&cpu_buffer->write_stamp, after, save_before);
2997 }
2998 }
2999 } else {
3000 u64 ts;
3001 /* SLOW PATH - Interrupted between A and C */
3002 after = local64_read(&cpu_buffer->write_stamp);
3003 ts = rb_time_stamp(cpu_buffer->buffer);
3004 barrier();
3005 /*E*/ if (write == (local_read(&tail_page->write) & RB_WRITE_MASK) &&
3006 after < ts) {
3007 /* Nothing came after this event between C and E */
3008 info->delta = ts - after;
3009 (void)local64_cmpxchg(&cpu_buffer->write_stamp, after, info->ts);
3010 info->ts = ts;
3011 } else {
3012 /*
3013 * Interrupted beween C and E:
3014 * Lost the previous events time stamp. Just set the
3015 * delta to zero, and this will be the same time as
3016 * the event this event interrupted. And the events that
3017 * came after this will still be correct (as they would
3018 * have built their delta on the previous event.
3019 */
3020 info->delta = 0;
3021 }
3022 if (info->add_timestamp == RB_ADD_STAMP_FORCE)
3023 info->add_timestamp = RB_ADD_STAMP_NORMAL;
3024 }
3025
3026 /*
3027 * If this is the first commit on the page, then it has the same
3028 * timestamp as the page itself.
3029 */
3030 if (unlikely(!tail && info->add_timestamp != RB_ADD_STAMP_FORCE && !abs))
3031 info->delta = 0;
3032
3033 /* We reserved something on the buffer */
3034
3035 event = __rb_page_index(tail_page, tail);
3036 rb_update_event(cpu_buffer, event, info);
3037
3038 local_inc(&tail_page->entries);
3039
3040 /*
3041 * If this is the first commit on the page, then update
3042 * its timestamp.
3043 */
3044 if (!tail)
3045 tail_page->page->time_stamp = info->ts;
3046
3047 /* account for these added bytes */
3048 local_add(info->length, &cpu_buffer->entries_bytes);
3049
3050 return event;
3051 }
3052

---
0-DAY CI Kernel Test Service, Intel Corporation
https://lists.01.org/hyperkitty/list/kbuild-all@xxxxxxxxxxxx

Attachment: .config.gz
Description: application/gzip