[BattOr] Reduce StartTracing time by about four seconds.

[BattOr] Reduce StartTracing time by about four seconds.

The BattOr automatically resets if the INIT message is received more
than once. Therefore, the first INIT message sent after a trace has
completed will inevitably cause a reset and command retry after four
seconds due a missing INIT ACK.

Adding a preemptive BattOr reset at the end of a successful
StopTracing command should shave one command retry (four seconds)
off of each BattOr trace.

BUG=711277

[aschulman, 2017-05-05 03:40:49]

Description was changed from

==========
[BattOr] Reduce StartTracing time by about four seconds.

The BattOr automatically resets if the INIT message is received more
than once. Therefore, the first INIT message sent after a trace has
completed will inevitably cause a reset and command retry after four
seconds due a missing INIT ACK.

Adding a preemptive BattOr reset at the end of a successful
StopTracing command should shave one command retry (four seconds)
off of each BattOr trace.

BUG=711277
==========

to

==========
[BattOr] Reduce StartTracing time by about four seconds.

The BattOr automatically resets if the INIT message is received more
than once. Therefore, the first INIT message sent after a trace has
completed will inevitably cause a reset and command retry after four
seconds due a missing INIT ACK.

Adding a preemptive BattOr reset at the end of a successful
StopTracing command should shave one command retry (four seconds)
off of each BattOr trace.

BUG=711277
==========

[aschulman, 2017-05-05 03:40:50]

aschulman@chromium.org changed reviewers:
+ nednguyen@google.com

[nednguyen, 2017-05-05 10:22:41]

nednguyen@google.com changed reviewers:
+ charliea@chromium.org, rnephew@chromium.org
- nednguyen@google.com

[nednguyen, 2017-05-05 10:22:49]

nednguyen@google.com changed reviewers:
+ nednguyen@google.com

[nednguyen, 2017-05-05 10:22:50]

I defer to Charlie & Randy

[charliea (OOO until 10-5), 2017-05-05 19:46:41]

Randy, would you mind prereviewing this and passing it onto me for final review?
I'd like to get to the point where we can have you be a secondary primary owner
in this codebase.

[rnephew (Reviews Here), 2017-05-09 14:44:28]

On 2017/05/05 19:46:41, charliea wrote:
> Randy, would you mind prereviewing this and passing it onto me for final
review?
> I'd like to get to the point where we can have you be a secondary primary
owner
> in this codebase.

this looks good to me, but I would like to see some unit tests to cover this new
command.

[charliea (OOO until 10-5), 2017-05-09 19:19:07]

I echo Randy's comment about unit tests

https://codereview.chromium.org/2859353003/diff/1/tools/battor_agent/battor_a...
File tools/battor_agent/battor_agent.cc (right):

https://codereview.chromium.org/2859353003/diff/1/tools/battor_agent/battor_a...
tools/battor_agent/battor_agent.cc:412: // Proactively reset the BattOr to speed
up the next trace.
I think this could be made clearer: for people stumbling through this code in
the future, it may be unclear why resetting the BattOr now will speed up the
trace in the future. That requires a surprisingly significant amount of
knowledge about how BattOrs work.

Could you elaborate in the comment about why this speeds things up?

[rnephew (Reviews Here), 2017-05-10 22:00:36]

Not necessarily in this CL, but should we expose the Reset command in the
battor_agent binary as its own command or is there nothing really added by
exposing it?

[aschulman, 2017-05-12 05:58:44]

On 2017/05/10 22:00:36, rnephew (Reviews Here) wrote:
> Not necessarily in this CL, but should we expose the Reset command in the
> battor_agent binary as its own command or is there nothing really added by
> exposing it?

I don't think there is much benefit to exposing reset to the BattOr shell.
Running start tracing is already a proxy for RESET if StartTracing was already
run. RESET is really just a way to proactively reset the BattOr firmware between
runs (exactly what we are using it for in this CL).

[charliea (OOO until 10-5), 2017-05-12 22:19:34]

On 2017/05/12 05:58:44, aschulman wrote:
> On 2017/05/10 22:00:36, rnephew (Reviews Here) wrote:
> > Not necessarily in this CL, but should we expose the Reset command in the
> > battor_agent binary as its own command or is there nothing really added by
> > exposing it?
> 
> I don't think there is much benefit to exposing reset to the BattOr shell.
> Running start tracing is already a proxy for RESET if StartTracing was already
> run. RESET is really just a way to proactively reset the BattOr firmware
between
> runs (exactly what we are using it for in this CL).

(Agree with Aaron here)

[aschulman, 2017-05-12 22:32:04]

I just uploaded a new patch that addresses most issues. However I'm fighting
with Mock to get it to deal with the new function calls (SendBytes RecvBytes...)
related to the addition of the RESET.

Does anyone who is an expert in Mock have a moment to help me figure out to
figure out why this is failing? I believe that I added the correct expectations
to the test case (you can see them in the latest patchset), but for some reason
it's still not working. I've put a few hours into it and I get the sense that I
am just missing something simple. Here is the log from the failure case I am
concerned about (StopTracing):

[ RUN      ] BattOrAgentTest.StopTracing
unknown file: Failure

Unexpected mock function call - returning directly.
    Function call: ReadMessage(5)
Google Mock tried the following 2 expectations, but none matched:

../../tools/battor_agent/battor_agent_unittest.cc:588: tried expectation #0:
EXPECT_CALL(*GetAgent()->GetConnection(),
ReadMessage(BATTOR_MESSAGE_TYPE_CONTROL_ACK))...
         Expected: the expectation is active
           Actual: it is retired
         Expected: to be called once
           Actual: called once - saturated and retired
../../tools/battor_agent/battor_agent_unittest.cc:608: tried expectation #1:
EXPECT_CALL(*GetAgent()->GetConnection(),
ReadMessage(BATTOR_MESSAGE_TYPE_SAMPLES))...
         Expected: all pre-requisites are satisfied
           Actual: the following immediate pre-requisites are not satisfied:
../../tools/battor_agent/battor_agent_unittest.cc:603: pre-requisite #0
                   (end of pre-requisites)
         Expected: to be called 4 times
           Actual: never called - unsatisfied and active
unknown file: Failure

Unexpected mock function call - returning directly.
    Function call: ReadMessage(5)
Google Mock tried the following 2 expectations, but none matched:

../../tools/battor_agent/battor_agent_unittest.cc:588: tried expectation #0:
EXPECT_CALL(*GetAgent()->GetConnection(),
ReadMessage(BATTOR_MESSAGE_TYPE_CONTROL_ACK))...
         Expected: the expectation is active
           Actual: it is retired
         Expected: to be called once
           Actual: called once - saturated and retired
../../tools/battor_agent/battor_agent_unittest.cc:608: tried expectation #1:
EXPECT_CALL(*GetAgent()->GetConnection(),
ReadMessage(BATTOR_MESSAGE_TYPE_SAMPLES))...
         Expected: all pre-requisites are satisfied
           Actual: the following immediate pre-requisites are not satisfied:
../../tools/battor_agent/battor_agent_unittest.cc:603: pre-requisite #0
                   (end of pre-requisites)
         Expected: to be called 4 times
           Actual: never called - unsatisfied and active
unknown file: Failure

Unexpected mock function call - returning directly.
    Function call: ReadMessage(5)
Google Mock tried the following 2 expectations, but none matched:

../../tools/battor_agent/battor_agent_unittest.cc:588: tried expectation #0:
EXPECT_CALL(*GetAgent()->GetConnection(),
ReadMessage(BATTOR_MESSAGE_TYPE_CONTROL_ACK))...
         Expected: the expectation is active
           Actual: it is retired
         Expected: to be called once
           Actual: called once - saturated and retired
../../tools/battor_agent/battor_agent_unittest.cc:608: tried expectation #1:
EXPECT_CALL(*GetAgent()->GetConnection(),
ReadMessage(BATTOR_MESSAGE_TYPE_SAMPLES))...
         Expected: all pre-requisites are satisfied
           Actual: the following immediate pre-requisites are not satisfied:
../../tools/battor_agent/battor_agent_unittest.cc:603: pre-requisite #0
                   (end of pre-requisites)
         Expected: to be called 4 times
           Actual: never called - unsatisfied and active
unknown file: Failure

Unexpected mock function call - returning directly.
    Function call: ReadMessage(5)
Google Mock tried the following 2 expectations, but none matched:

../../tools/battor_agent/battor_agent_unittest.cc:588: tried expectation #0:
EXPECT_CALL(*GetAgent()->GetConnection(),
ReadMessage(BATTOR_MESSAGE_TYPE_CONTROL_ACK))...
         Expected: the expectation is active
           Actual: it is retired
         Expected: to be called once
           Actual: called once - saturated and retired
../../tools/battor_agent/battor_agent_unittest.cc:608: tried expectation #1:
EXPECT_CALL(*GetAgent()->GetConnection(),
ReadMessage(BATTOR_MESSAGE_TYPE_SAMPLES))...
         Expected: all pre-requisites are satisfied
           Actual: the following immediate pre-requisites are not satisfied:
../../tools/battor_agent/battor_agent_unittest.cc:603: pre-requisite #0
                   (end of pre-requisites)
         Expected: to be called 4 times
           Actual: never called - unsatisfied and active
../../tools/battor_agent/battor_agent_unittest.cc:608: Failure
Actual function call count doesn't match
EXPECT_CALL(*GetAgent()->GetConnection(),
ReadMessage(BATTOR_MESSAGE_TYPE_SAMPLES))...
         Expected: to be called 4 times
           Actual: never called - unsatisfied and active
[  FAILED  ] BattOrAgentTest.StopTracing (0 ms)

https://codereview.chromium.org/2859353003/diff/1/tools/battor_agent/battor_a...
File tools/battor_agent/battor_agent.cc (right):

https://codereview.chromium.org/2859353003/diff/1/tools/battor_agent/battor_a...
tools/battor_agent/battor_agent.cc:412: // Proactively reset the BattOr to speed
up the next trace.
On 2017/05/09 19:19:06, charliea wrote:
> I think this could be made clearer: for people stumbling through this code in
> the future, it may be unclear why resetting the BattOr now will speed up the
> trace in the future. That requires a surprisingly significant amount of
> knowledge about how BattOrs work.
> 
> Could you elaborate in the comment about why this speeds things up?

agreed. I will do this as best as I can.

[charliea (OOO until 10-5), 2017-05-15 18:15:13]

I'm going to take a look at just the StopTracing test to try and make it easier
for myself.

I confirmed that the problem wasn't caused by any intertest interactions by
running it alone with:

$ out/Default/battor_agent_unittests
--gtest_filter='BattOrAgentTest.StopTracing' --single-process-tests

(http://stackoverflow.com/questions/33125953/how-can-i-tell-googlemock-to-stop...
suggested that intertest interactions might be a problem, so it seemed worth
checking.)

The message about an expectation being "retired" is sort of confusing, but I
think that
https://github.com/google/googlemock/blob/master/googlemock/docs/v1_7/ForDumm...
gives a pretty good rundown of what it means.

Essentially, the default behavior for gmock is that, if you say EXPECT_CALL(),
it will accept an infinite number of calls of whatever you put in parentheses.
If you do something like:

EXPECT_CALL(a->Connect(1));
EXPECT_CALL(a->Connect(2));

a->Connect(1);
a->Connect(2);

An error will be thrown saying that it didn't expect a->Connect(1), because the
second EXPECT_CALL completely overrides the first. In order to get the desired
behavior, we have to do:

testing::InSequence s;
EXPECT_CALL(a->Connect(1));
EXPECT_CALL(a->Connect(2));

a->Connect(1);
a->Connect(2);

Instantiating the testing::InSequence sends a signal to gmock that you should
queue the expectations and that when one gets "saturated" (i.e. the expectation
is met), you should move onto the next one.

The first thing that I did was move the EXPECT_CALL for the reset control
message send to after the EXPECT_CALL of the
ReadMessage(BATTOR_MESSAGE_TYPE_SAMPLES), because the RESET only takes place
after that. This looks like:
  
  ...

  // We send the agent four frames: a calibration frame, and two real frames,
  // and one zero-length frame to indicate that we're done.
  EXPECT_CALL(*GetAgent()->GetConnection(),
              ReadMessage(BATTOR_MESSAGE_TYPE_SAMPLES))
      .Times(4);

  // Ensure that the proactive reset message is be sent after the trace,
  BattOrControlMessage reset_msg{BATTOR_CONTROL_MESSAGE_TYPE_RESET, 0, 0};
  EXPECT_CALL(
      *GetAgent()->GetConnection(),
      SendBytes(BATTOR_MESSAGE_TYPE_CONTROL,
                BufferEq(&reset_msg, sizeof(reset_msg)), sizeof(reset_msg)));

  // Ensure that the proactive reset message ack is received.
  EXPECT_CALL(*GetAgent()->GetConnection(),
              ReadMessage(BATTOR_MESSAGE_TYPE_CONTROL_ACK));

  RunStopTracingTo(BattOrAgentState::SAMPLES_REQUEST_SENT);
 
  ...

Doing this gives makes it so that I only get one error from that test. That
error is:

../../tools/battor_agent/battor_agent_unittest.cc:613: Failure
Actual function call count doesn't match
EXPECT_CALL(*GetAgent()->GetConnection(),
ReadMessage(BATTOR_MESSAGE_TYPE_CONTROL_ACK))...
         Expected: to be called once
           Actual: never called - unsatisfied and active
[  FAILED  ] BattOrAgentTest.StopTracing (2 ms)
[----------] 1 test from BattOrAgentTest (2 ms total)

[----------] Global test environment tear-down
[==========] 1 test from 1 test case ran. (2 ms total)
[  PASSED  ] 0 tests.
[  FAILED  ] 1 test, listed below:
[  FAILED  ] BattOrAgentTest.StopTracing

 1 FAILED TEST

As discussed offline, that means we should remove the line that says:

  // Ensure that the proactive reset message ack is received.
  EXPECT_CALL(*GetAgent()->GetConnection(),
              ReadMessage(BATTOR_MESSAGE_TYPE_CONTROL_ACK));

when I remove that, the test passes.

The final test code is:

  testing::InSequence s;
  EXPECT_CALL(*GetAgent()->GetConnection(), Open());

  BattOrControlMessage request_eeprom_msg{
      BATTOR_CONTROL_MESSAGE_TYPE_READ_EEPROM, sizeof(BattOrEEPROM), 0};
  EXPECT_CALL(
      *GetAgent()->GetConnection(),
      SendBytes(BATTOR_MESSAGE_TYPE_CONTROL,
                BufferEq(&request_eeprom_msg, sizeof(request_eeprom_msg)),
                sizeof(request_eeprom_msg)));

  EXPECT_CALL(*GetAgent()->GetConnection(),
              ReadMessage(BATTOR_MESSAGE_TYPE_CONTROL_ACK));

  BattOrControlMessage request_samples_msg{
      BATTOR_CONTROL_MESSAGE_TYPE_READ_SD_UART, 0, 0};
  EXPECT_CALL(
      *GetAgent()->GetConnection(),
      SendBytes(BATTOR_MESSAGE_TYPE_CONTROL,
                BufferEq(&request_samples_msg, sizeof(request_samples_msg)),
                sizeof(request_samples_msg)));

  // We send the agent four frames: a calibration frame, and two real frames,
  // and one zero-length frame to indicate that we're done.
  EXPECT_CALL(*GetAgent()->GetConnection(),
              ReadMessage(BATTOR_MESSAGE_TYPE_SAMPLES))
      .Times(4);

  // Ensure that the proactive reset message is be sent after the trace,
  BattOrControlMessage reset_msg{BATTOR_CONTROL_MESSAGE_TYPE_RESET, 0, 0};
  EXPECT_CALL(
      *GetAgent()->GetConnection(),
      SendBytes(BATTOR_MESSAGE_TYPE_CONTROL,
                BufferEq(&reset_msg, sizeof(reset_msg)), sizeof(reset_msg)));

  RunStopTracingTo(BattOrAgentState::SAMPLES_REQUEST_SENT);

  // Send the calibration frame.
  BattOrFrameHeader cal_frame_header{0, 2 * sizeof(RawBattOrSample)};
  RawBattOrSample cal_frame[] = {
      RawBattOrSample{1, 1}, RawBattOrSample{2, 2},
  };
  OnMessageRead(true, BATTOR_MESSAGE_TYPE_SAMPLES,
                CreateFrame(cal_frame_header, cal_frame, 2));

  // Send the two real data frames.
  BattOrFrameHeader frame_header1{1, 3 * sizeof(RawBattOrSample)};
  RawBattOrSample frame1[] = {
      RawBattOrSample{1, 1}, RawBattOrSample{2, 2}, RawBattOrSample{3, 3},
  };
  OnMessageRead(true, BATTOR_MESSAGE_TYPE_SAMPLES,
                CreateFrame(frame_header1, frame1, 3));

  BattOrFrameHeader frame_header2{2, 1 * sizeof(RawBattOrSample)};
  RawBattOrSample frame2[] = {RawBattOrSample{1, 1}};
  OnMessageRead(true, BATTOR_MESSAGE_TYPE_SAMPLES,
                CreateFrame(frame_header2, frame2, 1));

  // Send an empty last frame to indicate that we're done.
  BattOrFrameHeader frame_header3{3, 0 * sizeof(RawBattOrSample)};
  OnMessageRead(true, BATTOR_MESSAGE_TYPE_SAMPLES,
                CreateFrame(frame_header3, nullptr, 0));

  // Bytes will be sent beause the proactive RESET message will be sent.
  OnBytesSent(true);

  EXPECT_TRUE(IsCommandComplete());
  EXPECT_EQ(BATTOR_ERROR_NONE, GetCommandError());
  EXPECT_EQ(
      "# BattOr\n# voltage_range [-2401.8, 2398.2] mV\n# "
      "current_range [-1200.9, 1199.1] mA\n"
      "# sample_rate 1000 Hz, gain 1.0x\n"
      "0.00 -0.3 -0.6\n1.00 0.3 0.6\n2.00 0.9 1.8\n3.00 -0.3 -0.6\n",
      GetTrace());

[charliea (OOO until 10-5), 2017-05-15 18:54:09]

Okay, onto another failing test:

Value of: IsCommandComplete()
  Actual: false
Expected: true
[  FAILED  ] BattOrAgentTest.StopTracingRetriesEEPROMRead (1 ms)

The contents of this test are really simple:

  RunStopTracingTo(BattOrAgentState::EEPROM_REQUEST_SENT);

  OnMessageRead(false, BATTOR_MESSAGE_TYPE_CONTROL_ACK, nullptr);

  OnMessageRead(true, BATTOR_MESSAGE_TYPE_CONTROL_ACK,
                ToCharVector(BattOrEEPROM()));

  // Give confirmation that the samples request was sent.
  OnBytesSent(true);

  BattOrFrameHeader cal_frame_header{0, sizeof(RawBattOrSample)};
  RawBattOrSample cal_frame[] = {RawBattOrSample{1, 1}};
  OnMessageRead(true, BATTOR_MESSAGE_TYPE_SAMPLES,
                CreateFrame(cal_frame_header, cal_frame, 1));

  BattOrFrameHeader frame_header{1, 0};
  OnMessageRead(true, BATTOR_MESSAGE_TYPE_SAMPLES,
                CreateFrame(frame_header, nullptr, 0));

  EXPECT_TRUE(IsCommandComplete());
  EXPECT_EQ(BATTOR_ERROR_NONE, GetCommandError());

In this case, it's not terminating because it's still waiting for the
confirmation that the RESET sent successfully. Adding a:

OnBytesSent(true);

before the final EXPECTs takes care of this and makes the test pass.

[charliea (OOO until 10-5), 2017-05-23 16:59:50]

Hey Aaron,

Just wanted to check in: are you waiting on anything to continue on this CL?

[aschulman, 2017-05-23 19:38:38]

On 2017/05/23 16:59:50, charliea wrote:
> Hey Aaron,
> 
> Just wanted to check in: are you waiting on anything to continue on this CL?

Nope, I was just waiting for the other CL to land before I uploaded the final
patch set for this CL. I just uploaded the final patch set though so this is now
ready for final review.

[charliea (OOO until 10-5), 2017-05-24 18:41:29]

lgtm w/ comment

Thanks for doing this Aaron!

https://codereview.chromium.org/2859353003/diff/40001/tools/battor_agent/batt...
File tools/battor_agent/battor_agent_unittest.cc (right):

https://codereview.chromium.org/2859353003/diff/40001/tools/battor_agent/batt...
tools/battor_agent/battor_agent_unittest.cc:783: OnBytesSent(true);
I think there should be a test where everything goes to plan, but then the send
of the RESET message fails. (based on the current implementation, this should
result in a send error, and we should just have a test making sure that behavior
is documented and working as intended)

[aschulman, 2017-06-09 00:33:20]

On 2017/05/24 18:41:29, charliea wrote:
> lgtm w/ comment
> 
> Thanks for doing this Aaron!
> 
>
https://codereview.chromium.org/2859353003/diff/40001/tools/battor_agent/batt...
> File tools/battor_agent/battor_agent_unittest.cc (right):
> 
>
https://codereview.chromium.org/2859353003/diff/40001/tools/battor_agent/batt...
> tools/battor_agent/battor_agent_unittest.cc:783: OnBytesSent(true);
> I think there should be a test where everything goes to plan, but then the
send
> of the RESET message fails. (based on the current implementation, this should
> result in a send error, and we should just have a test making sure that
behavior
> is documented and working as intended)

actually taking a closer look a the unit tests, the StopTracing unit tests are
quite broken. for example, the StopTracing() megatest is just a repeat of all of
the stuff in RunStopTracingTo() and the StopTracingFailed tests are restarting
RunStopTracingTo from the beginning which means they are not running accurate
tests. I will fix this all up in another CL and add RESET in this CL.
in_reply_to: 5709068098338816
send_mail: 1
subject: [BattOr] Reduce StartTracing time by about four seconds.