Ceph » rgw

version: ceph version 14.0.0-1433-g158ed61 (158ed6105d2a9def5988d370eb9b7bc076b82deb) nautilus (dev)

build with lttng, use lttng trace rgw op got:

[11:29:16.570588383] (+2.318415750) s130 rgw_op:before_data_transfer: { cpu_id = 15 }, { req_id = "431af2bd-19e5-4f95-9370-d3b7f5e84e43.4539.2" }
[11:29:17.571124538] (+1.000536155) s130 rgw_op:after_data_transfer: { cpu_id = 15 }, { req_id = "431af2bd-19e5-4f95-9370-d3b7f5e84e43.4539.2", ofs = 2048 }
[11:29:17.571141078] (+0.000016540) s130 rgw_op:processor_complete_enter: { cpu_id = 15 }, { req_id = "431af2bd-19e5-4f95-9370-d3b7f5e84e43.4539.2" }
[11:29:17.571179063] (+0.000037985) s130 rgw_rados:prepare_enter: { cpu_id = 15 }, { req_id = "431af2bd-19e5-4f95-9370-d3b7f5e84e43.4539.2" }
[11:29:17.591160083] (+0.019981020) s130 rgw_rados:prepare_exit: { cpu_id = 15 }, { req_id = "431af2bd-19e5-4f95-9370-d3b7f5e84e43.4539.2" }
[11:29:17.591161087] (+0.000001004) s130 rgw_rados:operate_enter: { cpu_id = 15 }, { req_id = "431af2bd-19e5-4f95-9370-d3b7f5e84e43.4539.2" }
[11:29:17.610238723] (+0.019077636) s130 rgw_rados:operate_exit: { cpu_id = 15 }, { req_id = "431af2bd-19e5-4f95-9370-d3b7f5e84e43.4539.2" }
[11:29:17.610539779] (+0.000301056) s130 rgw_rados:operate_enter: { cpu_id = 15 }, { req_id = "431af2bd-19e5-4f95-9370-d3b7f5e84e43.4539.2" }
[11:29:17.618347838] (+0.007808059) s130 rgw_rados:operate_exit: { cpu_id = 15 }, { req_id = "431af2bd-19e5-4f95-9370-d3b7f5e84e43.4539.2" }
[11:29:17.618351409] (+0.000003571) s130 rgw_rados:complete_enter: { cpu_id = 15 }, { req_id = "431af2bd-19e5-4f95-9370-d3b7f5e84e43.4539.2" }
[11:29:17.618380913] (+0.000029504) s130 rgw_rados:complete_exit: { cpu_id = 15 }, { req_id = "431af2bd-19e5-4f95-9370-d3b7f5e84e43.4539.2" }
[11:29:17.618390226] (+0.000009313) s130 rgw_op:processor_complete_exit: { cpu_id = 15 }, { req_id = "431af2bd-19e5-4f95-9370-d3b7f5e84e43.4539.2" }

then dig in rgw and civetweb, modify file(src/civetweb/src/civetweb.c) as below to log start_time/end_time of poll func:

static int
mg_poll(struct pollfd *pfd,
unsigned int n,
int milliseconds,
volatile int *stop_server) {
/* Call poll, but only for a maximum time of a few seconds.

• This will allow to stop the server after some seconds, instead
• of having to wait for a long socket timeout. /
  int ms_now = SOCKET_TIMEOUT_QUANTUM; / Sleep quantum in ms */

do {
int result;

if (stop_server) {
/ Shut down signal */
return -2;
}

if ((milliseconds >= 0) && (milliseconds < ms_now)) {
ms_now = milliseconds;
}

FILE fph = NULL;
fph = fopen("/tmp/test_civet_read_poll.txt", "a+");
struct timeval tv;
gettimeofday(&tv,NULL);
fprintf(fph, "CivetWeb::mg_poll start %ld timeout %d\n", tv.tv_sec*1000 + tv.tv_usec/1000, (int)ms_now);
result = poll(pfd, n, ms_now);
gettimeofday(&tv,NULL);
fprintf(fph, "CivetWeb::mg_poll end %ld res %d\n", tv.tv_sec*1000 + tv.tv_usec/1000, (int)result);
fclose(fph);
if (result != 0) {
/ Poll returned either success (1) or error (-1).

• Forward both to the caller. */
  return result;
  }

then output as below:

CivetWeb::mg_poll start 1532080345308 timeout 2000
CivetWeb::mg_poll end 1532080345308 res 1
CivetWeb::mg_poll start 1532080345312 timeout 2000
CivetWeb::mg_poll end 1532080346309 res 1
CivetWeb::mg_poll start 1532080346375 timeout 0
CivetWeb::mg_poll end 1532080346375 res 1

as is shown above, pool func cost almost 1 second