Yes, the time in execte_ctx account for the bulk of op_r_latency, but what I'm most curious about is the op_before_dequeue_op_lat. It shows that the op need to wait in osd's queue. And gdbpmp shows that 65.8% of the time spent in pthread_cond_timedwait because of the queue is empty. But the queue looks not empty and in fact I run enough rados bench to ensure enough stree. So I think if the tp_osd_tp could spend more time in ::process instead of pthread_cond_timedwait, the performance would be improved. Is my idea correct? Mark Nelson <mnelson@xxxxxxxxxx> 于2019年3月7日周四 下午8:42写道： > > 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 > >>
