Ok, so if you look in OSD.cc, you will see that the op_r_latency is
referred to as l_osd_op_r_lat in the code and is incremented in
PrimaryLogPG log_op_stats function along with a number of other
statistics. That is called in several places, but likely the most
interesting one in your case is toward the end of execute_ctx where
gdbpmp is showing that your tp_osd_tp thread is spending about 19% of
it's time. That log_op_stats call determines the latency based on the
time log_op_stats is called - m->get_recv_stamp(). So perhaps the
latency you are seeing in op_r_latency is primarily due to the time
spent working in execute_ctx?
Mark
On 3/6/19 9:32 PM, 韦皓诚 wrote:
Thank you~ No problem!
Mark Nelson <mnelson@xxxxxxxxxx> 于2019年3月6日周三 下午8:38写道：
On 3/6/19 2:41 AM, 韦皓诚 wrote:
Hi~
We use gdbpmp to profile wall time in osd and find that
pthread_cond_timedwait cost most of the real time(65.8%) in tp_osd_tp.
This means that the queue is empty in most of the time. But when we
use perfcount to analysis data reading, we find that the latency
between enqueue and dequeue is not negligible( about 40% in
op_r_latency). That may mean the queue is busy. So what cause the
contradiction between them?
Thank you~
Hi,
Can you post the gdbpmp trace and perfcount data? (feel free to send to
me if you don't want to post publicly). I'm not sure I have an answer
for you, but I'd start out by looking at what's happening the other 36%
of the time in tp_osd_tp.
Mark
