rgw: add latency info in the log of req done

[dongbula]

• References tracker ticket
• Updates documentation if necessary
• Includes tests for new functionality or reproducer for bug

[mattbenjamin]

@dongbula cant this be computed from the existing log messages?

[dongbula]

@mattbenjamin perfcounter stats some op's latency , but it is not existed in a log message now. I think it will be convenient if the latency can be found in a low-level log message

[dongbula]

@mattbenjamin hi, this is a simple modification, what do you think about it?

[robbat2]

@dongbula looks good to me, but a minor request for future enhancement: capture the time taking before the response header was sent and report that as well (my recent multi-delete improvement for example reduced the time-to-first-byte by 99.9% for some workloads)

[dongbula]

@robbat2 well, captured more times now

[stale]

This pull request has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs.
If you are a maintainer or core committer, please follow-up on this issue to identify what steps should be taken by the author to move this proposed change forward.
If you are the author of this pull request, thank you for your proposed contribution. If you believe this change is still appropriate, please ensure that any feedback has been addressed and ask for a code review.

[mattbenjamin]

unstale me

[mattbenjamin]

lgtm -- if this currently applies, don't see why we can't take this?

[cbodley]

time_elapsed() is already included in this log output because of ldpp_dout() and req_state::gen_prefix():

2018-11-07 10:09:50.918 7f7f157fa700 2 req 1 0.002s s3:list_buckets verifying op params
2018-11-07 10:09:50.918 7f7f157fa700 2 req 1 0.002s s3:list_buckets pre-executing
2018-11-07 10:09:50.918 7f7f157fa700 2 req 1 0.002s s3:list_buckets executing
2018-11-07 10:09:50.919 7f7f157fa700 2 req 1 0.003s s3:list_buckets completing
2018-11-07 10:09:50.919 7f7f157fa700 2 req 1 0.003s s3:list_buckets op status=0
2018-11-07 10:09:50.919 7f7f157fa700 2 req 1 0.003s http status=200

[mattbenjamin]

@cbodley ok, can we just close this one?

[cbodley]

@mattbenjamin the dout(1) << "====== req done req=" part at the end doesn't include time_elapsed(), so it's worth taking that change

[dongbula]

@cbodley have simplified it