Re: [PATCH v2] ring-buffer: Have nested events still record running time stamp
Hi Steven, Thank you for the patch! Yet something to improve: [auto build test ERROR on tip/perf/core] [also build test ERROR 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: openrisc-allyesconfig (attached as .config) compiler: or1k-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=openrisc If you fix the issue, kindly add following tag as appropriate Reported-by: kernel test robot All errors (new ones prefixed by >>): >> kernel/trace/ring_buffer.c:30:10: fatal error: asm/local64.h: No such file >> or directory 30 | #include | ^~~ compilation terminated. vim +30 kernel/trace/ring_buffer.c 28 29 #include > 30 #include 31 --- 0-DAY CI Kernel Test Service, Intel Corporation https://lists.01.org/hyperkitty/list/kbuild-...@lists.01.org .config.gz Description: application/gzip
Re: [PATCH v2] ring-buffer: Have nested events still record running time stamp
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 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, 2906struct 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(_page->write) & RB_WRITE_MASK; 2918 barrier(); 2919 before = local64_read(_buffer->before_stamp); 2920 after = local64_read(_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(_buffer->before_stamp, info->ts); 2952 2953 /*C*/ write = local_add_return(info->length, _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(_buffer->before_stamp); 2965 after = local64_read(_buffer->write_stamp); 2966 if (before != after) 2967 (void)local64_cmpxchg(_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(_buffer->write_stamp, info->ts); 2977
[PATCH v2] ring-buffer: Have nested events still record running time stamp
From: "Steven Rostedt (VMware)" Up until now, if an event is interrupted while it is recorded by an interrupt, and that interrupt records events, the time of those events will all be the same. This is because events only record the delta of the time since the previous event (or beginning of a page), and to handle updating the time keeping for that of nested events is extremely racy. After years of thinking about this and several failed attempts, I finally have a solution to solve this puzzle. The problem is that you need to atomically calculate the delta and then update the time stamp you made the delta from, as well as then record it into the buffer, all this while at any time an interrupt can come in and do the same thing. This is easy to solve with heavy weight atomics, but that would be detrimental to the performance of the ring buffer. The current state of affairs sacrificed the time deltas for nested events for performance. The reason for previous failed attempts at solving this puzzle was because I was trying to completely avoid slow atomic operations like cmpxchg. I final came to the conclusion to always avoid cmpxchg is not possible, which is why those previous attempts always failed. But it is possible to pick one path (the most common case) and avoid cmpxchg in that path, which is the "fast path". The most common case is that an event will not be interrupted and have other events added into it. An event can detect if it has interrupted another event, and for these cases we can make it the slow path and use the heavy operations like cmpxchg. One more player was added to the game that made this possible, and that is the "absolute timestamp" (by Tom Zanussi) that allows us to inject a full 59 bit time stamp. (Of course this breaks if a machine is running for more than 18 years without a reboot!). There's barrier() placements around for being paranoid, even when they are not needed because of other atomic functions near by. But those should not hurt, as if they are not needed, they basically become a nop. Note, this also makes the race window much smaller, which means there are less slow paths to slow down the performance. Here's the design of this solution: All this is per cpu, and only needs to worry about nested events (not parallel events). The players: write_tail: The index in the buffer where new events can be written to. It is incremented via local_add() to reserve space for a new event. before_stamp: A time stamp set by all events before reserving space. write_stamp: A time stamp updated by events after it has successfully reserved space. next_write: A copy of "write_tail" used to help with races. /* Save the current position of write */ [A]w = local_read(write_tail); barrier(); /* Read both before and write stamps before touching anything */ before = READ_ONCE(before_stamp); after = local_read(write_stamp); barrier(); /* * If before and after are the same, then this event is not * interrupting a time update. If it is, then reserve space for adding * a full time stamp (this can turn into a time extend which is * just an extended time delta but fill up the extra space). */ if (after != before) abs = true; ts = clock(); /* Now update the before_stamp (everyone does this!) */ [B]WRITE_ONCE(before_stamp, ts); /* Read the current next_write and update it to what we want write * to be after we reserve space. */ next = READ_ONCE(next_write); WRITE_ONCE(next_write, w + len); /* Now reserve space on the buffer */ [C]write = local_add_return(len, write_tail); /* Set tail to be were this event's data is */ tail = write - len; if (w == tail) { /* Nothing interrupted this between A and C */ [D]local_set(write_stamp, ts); barrier(); [E]save_before = READ_ONCE(before_stamp); if (!abs) { /* This did not interrupt a time update */ delta = ts - after; } else { delta = ts; /* The full time stamp will be in use */ } if (ts != save_before) { /* slow path - Was interrupted between C and E */ /* The update to write_stamp could have overwritten the update to * it by the interrupting event, but before and after should be * the same for all completed top events */ after = local_read(write_stamp); if (save_before > after) local_cmpxchg(write_stamp, after, save_before); } } else { /* slow path - Interrupted between A and C */ after =