function_graph plugin fails to log function_entry records when tracing_threshold is non zero

Question

function_graph plugin fails to log function_entry records when tracing_thresh is set to non-zero value, i am using ubuntu with 4.15 kernel. Looks like, i have stumbled on a bug discussed at https://lore.kernel.org/patchwork/patch/188477/ . Please advise, steps to reproduce

root@rk-VirtualBox:/home/rk# echo 50 >  /sys/kernel/debug/tracing/tracing_thresh 
root@rk-VirtualBox:/home/rk# trace-cmd record -P $(pidof Xorg)  -p function_graph   -g "unix_stream_recvmsg" 
  plugin 'function_graph'
Hit Ctrl^C to stop recording

^CKernel buffer statistics:
  Note: "entries" are the entries left in the kernel ring buffer and are not
        recorded in the trace data. They should all be zero.

CPU: 0
entries: 0
overrun: 0
commit overrun: 0
bytes: 0
oldest event ts:  8174.755713
now ts: 10835.724188
dropped events: 0
read events: 0

CPU: 1
entries: 0
overrun: 0
commit overrun: 0
bytes: 1064
oldest event ts: 10823.335096
now ts: 10835.724471
dropped events: 0
read events: 21

CPU0 data recorded at offset=0x48c000
    0 bytes in size
CPU1 data recorded at offset=0x48c000
    4096 bytes in size
root@rk-VirtualBox:/home/rk# trace-cmd report -l 
version = 6
CPU 0 is empty
cpus=2
    Xorg-1629    1.... 10823.335096: funcgraph_exit:       + 69.854 us  |    }
    Xorg-1629    1.N.. 10823.335168: funcgraph_exit:       ! 144.131 us |  }
    Xorg-1629    1.... 10823.484822: funcgraph_exit:       + 65.652 us  |    }
    Xorg-1629    1.... 10823.484830: funcgraph_exit:       + 79.146 us  |  }
    Xorg-1629    1.... 10824.115913: funcgraph_exit:       + 61.892 us  |    }
    Xorg-1629    1.... 10824.115915: funcgraph_exit:       + 65.617 us  |  }
    Xorg-1629    1.... 10824.369064: funcgraph_exit:       + 53.736 us  |              }
    Xorg-1629    1.... 10824.369067: funcgraph_exit:       + 59.413 us  |            }
    Xorg-1629    1.... 10824.369068: funcgraph_exit:       + 61.351 us  |          }
    Xorg-1629    1.... 10824.369073: funcgraph_exit:       + 66.796 us  |        }
    Xorg-1629    1.... 10824.369077: funcgraph_exit:       + 70.633 us  |      }
    Xorg-1629    1.... 10824.369080: funcgraph_exit:       + 87.385 us  |    }
    Xorg-1629    1.... 10824.369081: funcgraph_exit:       + 89.105 us  |  }
    Xorg-1629    1.... 10824.588131: funcgraph_exit:       + 74.199 us  |    }
    Xorg-1629    1.... 10824.588133: funcgraph_exit:       + 79.437 us  |  }
    Xorg-1629    1.... 10825.359456: funcgraph_exit:       + 53.650 us  |        }
    Xorg-1629    1.... 10825.359461: funcgraph_exit:       + 60.938 us  |      }
    Xorg-1629    1.... 10825.359466: funcgraph_exit:       + 78.474 us  |    }
    Xorg-1629    1.... 10825.359466: funcgraph_exit:       + 80.188 us  |  }
    Xorg-1629    1.... 10826.588161: funcgraph_exit:       + 50.897 us  |    }
    Xorg-1629    1.... 10826.588164: funcgraph_exit:       + 77.478 us  |  }

Answer 1

The below code worked , some how was not able to get trace-cmd working.

#!/bin/bash 
#-------------
echo 120 > /sys/kernel/debug/tracing/tracing_thresh
echo function_graph > /sys/kernel/debug/tracing/current_tracer
echo funcgraph-abstime  > /sys/kernel/debug/tracing/trace_options
echo funcgraph-tail >> /sys/kernel/debug/tracing/trace_options
echo funcgraph-cpu >> /sys/kernel/debug/tracing/trace_options
echo sleep-time >> /sys/kernel/debug/tracing/trace_options
echo "*rcu*" >> /sys/kernel/debug/tracing/set_ftrace_notrace
echo "*spin*" >> /sys/kernel/debug/tracing/set_ftrace_notrace
echo unix_stream_sendmsg >/sys/kernel/debug/tracing/set_graph_function
echo "------------------------------------------------" > /sys/kernel/debug/tracing/trace_marker
echo 1  > /sys/kernel/debug/tracing/tracing_on
echo "$(pidof Xorg)" > /sys/kernel/debug/tracing/set_ftrace_pid
sleep 300;
echo 0 > /sys/kernel/debug/tracing/tracing_on
cat /sys/kernel/debug/tracing/trace



output:
19724.515607 |   1) ! 150.896 us  |  } /* unix_stream_sendmsg */
19724.516842 |   1) ! 122.788 us  |                } /* try_to_wake_up */
19724.516845 |   1) ! 127.905 us  |              } /* default_wake_function */
19724.516847 |   1) ! 129.967 us  |            } /* pollwake */
19724.516848 |   1) ! 132.662 us  |          } /* __wake_up_common */
19724.516849 |   1) ! 134.316 us  |        } /* __wake_up_common_lock */
19724.516850 |   1) ! 135.651 us  |      } /* __wake_up_sync_key */
19724.516852 |   1) ! 137.699 us  |    } /* sock_def_readable */
19724.516854 |   1) ! 169.421 us  |  } /* unix_stream_sendmsg */
19724.518544 |   1) ! 128.609 us  |  } /* unix_stream_sendmsg */
19725.371957 |   1) ! 165.194 us  |  } /* unix_stream_sendmsg */
19725.543227 |   1) ! 126.127 us  |  } /* unix_stream_sendmsg */

still not able to understand why last 3 rows are repeating with out breakup.