Finalize PerformanceSummary implementation

Note: Opened a separate CL due to rebasing. Feature-wise this CL adds to 302360043 with (1) number of objects/files transferred and (2) timestamp. This also fixes the testMetricsPosting failure due to exact ordering.

Commit message:
Implement PerformanceSummary analytics collection

This commit implements collection of performance statistics after cp and rsync are run to send to Google Analytics.

[jessicazhu, 2016-08-18 21:27:00]

https://codereview.appspot.com/303350043/diff/40001/gslib/command.py
File gslib/command.py (left):

https://codereview.appspot.com/303350043/diff/40001/gslib/command.py#oldcode1923
gslib/command.py:1923: args_iterator.ProcessSourceUrlType(self.status_queue,
args)
This was a rebasing error.

https://codereview.appspot.com/303350043/diff/40001/gslib/tests/test_metrics.py
File gslib/tests/test_metrics.py (left):

https://codereview.appspot.com/303350043/diff/40001/gslib/tests/test_metrics....
gslib/tests/test_metrics.py:85: ('ea=retryable_error_type_2'), ('cm2=1')]),
This was a rebasing error.

https://codereview.appspot.com/303350043/diff/40001/gslib/thread_message.py
File gslib/thread_message.py (right):

https://codereview.appspot.com/303350043/diff/40001/gslib/thread_message.py#n...
gslib/thread_message.py:89: self.is_service_error = False
This was a rebasing error.

[thobrla, 2016-08-18 23:22:42]

https://codereview.appspot.com/303350043/diff/40001/gslib/tests/test_metrics.py
File gslib/tests/test_metrics.py (right):

https://codereview.appspot.com/303350043/diff/40001/gslib/tests/test_metrics....
gslib/tests/test_metrics.py:702: # The metric body might not be in the same
order.
Why not define an order when building the POST?

https://codereview.appspot.com/303350043/diff/40001/gslib/thread_message.py
File gslib/thread_message.py (right):

https://codereview.appspot.com/303350043/diff/40001/gslib/thread_message.py#n...
gslib/thread_message.py:338: self.collected_info = {'uses_slice': uses_slice}
Why did we eliminate all of these?

[jessicazhu, 2016-08-19 17:02:52]

https://codereview.appspot.com/303350043/diff/40001/gslib/tests/test_metrics.py
File gslib/tests/test_metrics.py (right):

https://codereview.appspot.com/303350043/diff/40001/gslib/tests/test_metrics....
gslib/tests/test_metrics.py:702: # The metric body might not be in the same
order.
On 2016/08/18 23:22:41, thobrla wrote:
> Why not define an order when building the POST?

You're right, that would make testing a lot less painful. Done.

https://codereview.appspot.com/303350043/diff/40001/gslib/thread_message.py
File gslib/thread_message.py (right):

https://codereview.appspot.com/303350043/diff/40001/gslib/thread_message.py#n...
gslib/thread_message.py:338: self.collected_info = {'uses_slice': uses_slice}
On 2016/08/18 23:22:41, thobrla wrote:
> Why did we eliminate all of these?

Originally we were posting has_file_src, has_cloud_src, is_daisy_chain, and
provider_type from the NameExpansionIterator wrapper. I changed that so that
this info would be logged at the end of the top-level Apply call, which doesn't
require a post to the status queue. Originally num_objects_transferred updated
that metric every time a FileMessage was posted, but now this number gets logged
only when a FinalMessage is posted. I left collected_info as a dictionary so
that it would be easy in the future to add more parameters to this if necessary.

[jessicazhu, 2016-08-19 20:45:56]

As discussed offline, made changes to thread idle time collection.

[thobrla, 2016-08-19 21:07:12]

https://codereview.appspot.com/303350043/diff/140001/gslib/command.py
File gslib/command.py (right):

https://codereview.appspot.com/303350043/diff/140001/gslib/command.py#newcode...
gslib/command.py:2065: @CaptureAndLogException
Since this exception can happen during normal execution, do we really want to
log it?  Also the error message will say it happened during metrics collection,
which is not quite accurate.

https://codereview.appspot.com/303350043/diff/140001/gslib/command.py#newcode...
gslib/command.py:2150: self.total_execution_time += exec_time
Since we initialize total_execution_time to self.start_block_time - init_time,
won't the first call record double the actual execution time for thread startup?

Since end_block_time = init_time, could we just leave this as-is and initialize
total_execution_time to 0 in init?

https://codereview.appspot.com/303350043/diff/140001/gslib/command.py#newcode...
gslib/command.py:2157: def AggregateStat(self, end_time):
We're only aggregating idle time here, not execution time, so should this
function be called AggregateIdleTime?

https://codereview.appspot.com/303350043/diff/140001/gslib/command.py#newcode...
gslib/command.py:2159: # Apply ended not during a task_queue.get() call, or
there was an exception
Consider moving these comments inside the if block.

https://codereview.appspot.com/303350043/diff/140001/gslib/command.py#newcode...
gslib/command.py:2159: # Apply ended not during a task_queue.get() call, or
there was an exception
Consider: "Apply ended before we blocked on task_queue.get()"

https://codereview.appspot.com/303350043/diff/140001/gslib/command.py#newcode...
gslib/command.py:2164: # Apply ended during a task_queue.get() call, or there
was an exception
Consider: "Apply ended while we were blocked on task_queue.get()"

https://codereview.appspot.com/303350043/diff/140001/gslib/command.py#newcode...
gslib/command.py:2168: elif self.start_block_time > self.end_block_time:
There's a third case where start_block_time and end_block_time are equal - what
do we do in that case (it seems like we'll leave idle time alone but it may be
useful to explain why).

[thobrla, 2016-08-19 21:16:17]

https://codereview.appspot.com/303350043/diff/40001/gslib/thread_message.py
File gslib/thread_message.py (right):

https://codereview.appspot.com/303350043/diff/40001/gslib/thread_message.py#n...
gslib/thread_message.py:338: self.collected_info = {'uses_slice': uses_slice}
On 2016/08/19 17:02:52, jessicazhu wrote:
> On 2016/08/18 23:22:41, thobrla wrote:
> > Why did we eliminate all of these?
> 
> Originally we were posting has_file_src, has_cloud_src, is_daisy_chain, and
> provider_type from the NameExpansionIterator wrapper. I changed that so that
> this info would be logged at the end of the top-level Apply call, which
doesn't
> require a post to the status queue. Originally num_objects_transferred updated
> that metric every time a FileMessage was posted, but now this number gets
logged
> only when a FinalMessage is posted. I left collected_info as a dictionary so
> that it would be easy in the future to add more parameters to this if
necessary.

I don't feel strongly about this, but we shouldn't extend this to be a dict
until we actually need it.

[jessicazhu, 2016-08-19 23:11:11]

https://codereview.appspot.com/303350043/diff/40001/gslib/thread_message.py
File gslib/thread_message.py (right):

https://codereview.appspot.com/303350043/diff/40001/gslib/thread_message.py#n...
gslib/thread_message.py:338: self.collected_info = {'uses_slice': uses_slice}
On 2016/08/19 21:16:17, thobrla wrote:
> On 2016/08/19 17:02:52, jessicazhu wrote:
> > On 2016/08/18 23:22:41, thobrla wrote:
> > > Why did we eliminate all of these?
> > 
> > Originally we were posting has_file_src, has_cloud_src, is_daisy_chain, and
> > provider_type from the NameExpansionIterator wrapper. I changed that so that
> > this info would be logged at the end of the top-level Apply call, which
> doesn't
> > require a post to the status queue. Originally num_objects_transferred
updated
> > that metric every time a FileMessage was posted, but now this number gets
> logged
> > only when a FinalMessage is posted. I left collected_info as a dictionary so
> > that it would be easy in the future to add more parameters to this if
> necessary.
> 
> I don't feel strongly about this, but we shouldn't extend this to be a dict
> until we actually need it.

Done.

https://codereview.appspot.com/303350043/diff/140001/gslib/command.py
File gslib/command.py (right):

https://codereview.appspot.com/303350043/diff/140001/gslib/command.py#newcode...
gslib/command.py:2065: @CaptureAndLogException
On 2016/08/19 21:07:12, thobrla wrote:
> Since this exception can happen during normal execution, do we really want to
> log it?  Also the error message will say it happened during metrics
collection,
> which is not quite accurate.

Done.

https://codereview.appspot.com/303350043/diff/140001/gslib/command.py#newcode...
gslib/command.py:2150: self.total_execution_time += exec_time
On 2016/08/19 21:07:12, thobrla wrote:
> Since we initialize total_execution_time to self.start_block_time - init_time,
> won't the first call record double the actual execution time for thread
startup?
> 
> Since end_block_time = init_time, could we just leave this as-is and
initialize
> total_execution_time to 0 in init?

No; the first call to WorkerThread._StartBlockedTime initializes the thread
stat, but doesn't call ThreadStat.StartBlockedTime. That being said, it makes
more sense to do what you're saying, and call ThreadStat.StartBlockedTime after
its initialization.

https://codereview.appspot.com/303350043/diff/140001/gslib/command.py#newcode...
gslib/command.py:2157: def AggregateStat(self, end_time):
On 2016/08/19 21:07:12, thobrla wrote:
> We're only aggregating idle time here, not execution time, so should this
> function be called AggregateIdleTime?

We're aggregating one or the other.

https://codereview.appspot.com/303350043/diff/140001/gslib/command.py#newcode...
gslib/command.py:2159: # Apply ended not during a task_queue.get() call, or
there was an exception
On 2016/08/19 21:07:12, thobrla wrote:
> Consider moving these comments inside the if block.

Done.

https://codereview.appspot.com/303350043/diff/140001/gslib/command.py#newcode...
gslib/command.py:2159: # Apply ended not during a task_queue.get() call, or
there was an exception
On 2016/08/19 21:07:12, thobrla wrote:
> Consider: "Apply ended before we blocked on task_queue.get()"

Done.

https://codereview.appspot.com/303350043/diff/140001/gslib/command.py#newcode...
gslib/command.py:2164: # Apply ended during a task_queue.get() call, or there
was an exception
On 2016/08/19 21:07:12, thobrla wrote:
> Consider: "Apply ended while we were blocked on task_queue.get()"

Done.

https://codereview.appspot.com/303350043/diff/140001/gslib/command.py#newcode...
gslib/command.py:2168: elif self.start_block_time > self.end_block_time:
On 2016/08/19 21:07:12, thobrla wrote:
> There's a third case where start_block_time and end_block_time are equal -
what
> do we do in that case (it seems like we'll leave idle time alone but it may be
> useful to explain why).

In the third case I don't think we do anything -- should I add an else: pass
with a comment?