Chromium Code Reviews
|
|
Chromium Code Reviews
Issue
953223002:
Include time elapsed since start of a remoting session in each log entry. (Closed)
DescriptionInclude time elapsed since start of a remoting session in each log entry.
BUG=461610
Executed run_webapp_unittest.py with these changes and all tests passed.
Committed: https://crrev.com/fcf59efc9dd11d746b0b8c8d26f34d41e94c5892
Cr-Commit-Position: refs/heads/master@{#318738}
Patch Set 1 #
Total comments: 4
Patch Set 2 : Rename constant to include time unit, and remove superfluous constant. #
Total comments: 6
Patch Set 3 : Upon each session state change, log the time taken to get to that state. #Patch Set 4 : Remove logging of elapsed time for session strategy progress. #
Total comments: 6
Patch Set 5 : Calculate elapsed time for the signal strategy progress event as well. #
Total comments: 6
Patch Set 6 : Record elapsed time every time we log something. #
Total comments: 2
Patch Set 7 : Set session start time in constructor. #
Total comments: 2
Patch Set 8 : Remove now unnecessary session duration logging. #
Messages
Total messages: 39 (18 generated)
Patchset #1 (id:1) has been deleted
Patchset #1 (id:20001) has been deleted
anandc@chromium.org changed reviewers: + jamiewalch@chromium.org
Jamie, PTAL. Sriram and Gary, FYI. I'd like to get some feedback first on whether this is the right approach to logging this. Once we have that figured out, I'll split the time logged to be: time to connect to talk time to connect to host
sriramsr@chromium.org changed reviewers: + sriramsr@chromium.org
https://codereview.chromium.org/953223002/diff/40001/remoting/webapp/crd/js/s... File remoting/webapp/crd/js/server_log_entry.js (right): https://codereview.chromium.org/953223002/diff/40001/remoting/webapp/crd/js/s... remoting/webapp/crd/js/server_log_entry.js:53: remoting.ServerLogEntry.VALUE_EVENT_NAME_TOTAL_TIME_FOR_INITIAL_CONNECT_ = This is little confusing as why there is value of the name. If the value is always going to be the name of the event then it would make sense to actually use event key as value instead of a different string. https://codereview.chromium.org/953223002/diff/40001/remoting/webapp/crd/js/s... remoting/webapp/crd/js/server_log_entry.js:56: remoting.ServerLogEntry.KEY_TOTAL_TIME_FOR_INITIAL_CONNECT_ = Include the unit for time in the name.
https://codereview.chromium.org/953223002/diff/40001/remoting/webapp/crd/js/s... File remoting/webapp/crd/js/server_log_entry.js (right): https://codereview.chromium.org/953223002/diff/40001/remoting/webapp/crd/js/s... remoting/webapp/crd/js/server_log_entry.js:53: remoting.ServerLogEntry.VALUE_EVENT_NAME_TOTAL_TIME_FOR_INITIAL_CONNECT_ = On 2015/02/25 19:50:44, Sriram wrote: > This is little confusing as why there is value of the name. If the value is > always going to be the name of the event then it would make sense to actually > use event key as value instead of a different string. Done. https://codereview.chromium.org/953223002/diff/40001/remoting/webapp/crd/js/s... remoting/webapp/crd/js/server_log_entry.js:56: remoting.ServerLogEntry.KEY_TOTAL_TIME_FOR_INITIAL_CONNECT_ = On 2015/02/25 19:50:44, Sriram wrote: > Include the unit for time in the name. Done.
https://codereview.chromium.org/953223002/diff/60001/remoting/webapp/crd/js/d... File remoting/webapp/crd/js/desktop_viewport.js (right): https://codereview.chromium.org/953223002/diff/60001/remoting/webapp/crd/js/d... remoting/webapp/crd/js/desktop_viewport.js:345: remoting.clientSession.logToServer.logTotalTimeForInitialConnection(); I would prefer that we don't introduce a dependency on remoting.clientSession in this class. Doing this logging in onVideoStreamingStarted would seem more appropriate. Kelvin can probably chime in here as to whether or not that's a good idea. In any case, you shouldn't call this multiple times, which will happen with this layout, since I think updateDimensions is called whenever the remote desktop size changes. An alternative would be to hook the connected event directly; you'd lose information as to whether or not the video stream works, but that feels orthogonal to the time taken to connect. https://codereview.chromium.org/953223002/diff/60001/remoting/webapp/crd/js/l... File remoting/webapp/crd/js/log_to_server.js (right): https://codereview.chromium.org/953223002/diff/60001/remoting/webapp/crd/js/l... remoting/webapp/crd/js/log_to_server.js:103: (new Date().getTime() - this.sessionStartTime_) / 1000.0); I would log in ms, not s (that's what I used for the signal strategy). https://codereview.chromium.org/953223002/diff/60001/remoting/webapp/crd/js/s... File remoting/webapp/crd/js/server_log_entry.js (right): https://codereview.chromium.org/953223002/diff/60001/remoting/webapp/crd/js/s... remoting/webapp/crd/js/server_log_entry.js:54: 'total-time-for-initial-connect'; I don't think we should need a separate log entry for this. We already have session-state, and what we're interested in here is the time taken to reach a certain state. It would be better to add an elapsed-time field to session-state events (we already have one for signal-strategy-progress--you can either duplicate it or rename it), I think, and then filter on the one we're interested in.
Patchset #3 (id:80001) has been deleted
Patchset #3 (id:100001) has been deleted
Patchset #4 (id:140001) has been deleted
Thanks Jamie. PTAL. https://codereview.chromium.org/953223002/diff/60001/remoting/webapp/crd/js/d... File remoting/webapp/crd/js/desktop_viewport.js (right): https://codereview.chromium.org/953223002/diff/60001/remoting/webapp/crd/js/d... remoting/webapp/crd/js/desktop_viewport.js:345: remoting.clientSession.logToServer.logTotalTimeForInitialConnection(); On 2015/02/25 21:12:35, Jamie wrote: > I would prefer that we don't introduce a dependency on remoting.clientSession in > this class. Doing this logging in onVideoStreamingStarted would seem more > appropriate. Kelvin can probably chime in here as to whether or not that's a > good idea. > > In any case, you shouldn't call this multiple times, which will happen with this > layout, since I think updateDimensions is called whenever the remote desktop > size changes. An alternative would be to hook the connected event directly; > you'd lose information as to whether or not the video stream works, but that > feels orthogonal to the time taken to connect. The user perceives a connection has been completed only when video-streaming begins. As discussed offline, I'll create a new session-state for that, in a separate CL. https://codereview.chromium.org/953223002/diff/60001/remoting/webapp/crd/js/l... File remoting/webapp/crd/js/log_to_server.js (right): https://codereview.chromium.org/953223002/diff/60001/remoting/webapp/crd/js/l... remoting/webapp/crd/js/log_to_server.js:103: (new Date().getTime() - this.sessionStartTime_) / 1000.0); On 2015/02/25 21:12:35, Jamie wrote: > I would log in ms, not s (that's what I used for the signal strategy). Done. https://codereview.chromium.org/953223002/diff/60001/remoting/webapp/crd/js/s... File remoting/webapp/crd/js/server_log_entry.js (right): https://codereview.chromium.org/953223002/diff/60001/remoting/webapp/crd/js/s... remoting/webapp/crd/js/server_log_entry.js:54: 'total-time-for-initial-connect'; On 2015/02/25 21:12:35, Jamie wrote: > I don't think we should need a separate log entry for this. We already have > session-state, and what we're interested in here is the time taken to reach a > certain state. It would be better to add an elapsed-time field to session-state > events (we already have one for signal-strategy-progress--you can either > duplicate it or rename it), I think, and then filter on the one we're interested > in. Done.
https://codereview.chromium.org/953223002/diff/150001/remoting/webapp/crd/js/... File remoting/webapp/crd/js/log_to_server.js (right): https://codereview.chromium.org/953223002/diff/150001/remoting/webapp/crd/js/... remoting/webapp/crd/js/log_to_server.js:77: entry.addTimeToReachStateMs(timeToReachThisState); This should either be added at a lower level (if you want to include it all events--which I recommend) or you need to reinstate the elapsed time for signal strategy progress events, otherwise this CL removes it. https://codereview.chromium.org/953223002/diff/150001/remoting/webapp/crd/js/... File remoting/webapp/crd/js/server_log_entry.js (right): https://codereview.chromium.org/953223002/diff/150001/remoting/webapp/crd/js/... remoting/webapp/crd/js/server_log_entry.js:51: 'time-to-reach-state'; I think simply "elapsed-time" is a better name for this, as it need not refer to a session state change event. https://codereview.chromium.org/953223002/diff/150001/remoting/webapp/crd/js/... remoting/webapp/crd/js/server_log_entry.js:320: No need for an extra blank line here.
Patchset #5 (id:170001) has been deleted
Thanks Jamie. PTAL. https://codereview.chromium.org/953223002/diff/150001/remoting/webapp/crd/js/... File remoting/webapp/crd/js/log_to_server.js (right): https://codereview.chromium.org/953223002/diff/150001/remoting/webapp/crd/js/... remoting/webapp/crd/js/log_to_server.js:77: entry.addTimeToReachStateMs(timeToReachThisState); On 2015/02/26 20:32:06, Jamie wrote: > This should either be added at a lower level (if you want to include it all > events--which I recommend) or you need to reinstate the elapsed time for signal > strategy progress events, otherwise this CL removes it. Done. Move further down in this function. https://codereview.chromium.org/953223002/diff/150001/remoting/webapp/crd/js/... File remoting/webapp/crd/js/server_log_entry.js (right): https://codereview.chromium.org/953223002/diff/150001/remoting/webapp/crd/js/... remoting/webapp/crd/js/server_log_entry.js:51: 'time-to-reach-state'; On 2015/02/26 20:32:06, Jamie wrote: > I think simply "elapsed-time" is a better name for this, as it need not refer to > a session state change event. Done. https://codereview.chromium.org/953223002/diff/150001/remoting/webapp/crd/js/... remoting/webapp/crd/js/server_log_entry.js:320: On 2015/02/26 20:32:06, Jamie wrote: > No need for an extra blank line here. Done.
https://codereview.chromium.org/953223002/diff/170002/remoting/webapp/crd/js/... File remoting/webapp/crd/js/fallback_signal_strategy.js (right): https://codereview.chromium.org/953223002/diff/170002/remoting/webapp/crd/js/... remoting/webapp/crd/js/fallback_signal_strategy.js:394: 'elapsed': new Date().getTime() - this.startTime_ Not that log_to_server is handling elapsed times, you don't need this (or this.startTime_) any more. https://codereview.chromium.org/953223002/diff/170002/remoting/webapp/crd/js/... File remoting/webapp/crd/js/log_to_server.js (right): https://codereview.chromium.org/953223002/diff/170002/remoting/webapp/crd/js/... remoting/webapp/crd/js/log_to_server.js:89: entry.addElapsedTimeMs(elapsedTimeInMs); This is still only being added for session state change events. We need it for signal strategy events at least, and I think there's value in having it for all events. I haven't looked in detail, but I think you'll need to add it to the log_() method, and look into how the session start time is set. You need to make sure it's set before the first log message is sent, but if the LogToServer instance is re-used between connections, you'll also need to reset it--it's probably better to make sure the LogToServer is not re-used. https://codereview.chromium.org/953223002/diff/170002/remoting/webapp/crd/js/... File remoting/webapp/crd/js/server_log_entry.js (right): https://codereview.chromium.org/953223002/diff/170002/remoting/webapp/crd/js/... remoting/webapp/crd/js/server_log_entry.js:51: 'elapsed-time'; This will now all fit on one line.
Patchset #6 (id:190001) has been deleted
Patchset #6 (id:210001) has been deleted
Patchset #6 (id:230001) has been deleted
Thanks Jamie. PTAL. https://codereview.chromium.org/953223002/diff/170002/remoting/webapp/crd/js/... File remoting/webapp/crd/js/fallback_signal_strategy.js (right): https://codereview.chromium.org/953223002/diff/170002/remoting/webapp/crd/js/... remoting/webapp/crd/js/fallback_signal_strategy.js:394: 'elapsed': new Date().getTime() - this.startTime_ On 2015/02/27 02:24:46, Jamie wrote: > Not that log_to_server is handling elapsed times, you don't need this (or > this.startTime_) any more. Done. https://codereview.chromium.org/953223002/diff/170002/remoting/webapp/crd/js/... File remoting/webapp/crd/js/log_to_server.js (right): https://codereview.chromium.org/953223002/diff/170002/remoting/webapp/crd/js/... remoting/webapp/crd/js/log_to_server.js:89: entry.addElapsedTimeMs(elapsedTimeInMs); On 2015/02/27 02:24:46, Jamie wrote: > This is still only being added for session state change events. We need it for > signal strategy events at least, and I think there's value in having it for all > events. I haven't looked in detail, but I think you'll need to add it to the > log_() method, and look into how the session start time is set. You need to make > sure it's set before the first log message is sent, but if the LogToServer > instance is re-used between connections, you'll also need to reset it--it's > probably better to make sure the LogToServer is not re-used. Done. LogToServer is reset at the start of each session. See: https://code.google.com/p/chromium/codesearch#chromium/src/remoting/webapp/cr... Session start time is being set when we first get a "Connecting" event. See line 65 above. The first call to log_ is made right after the first "Connecting" event. I confirmed this by checking values in the console debugger. Based on all that, adding the elapsed-time field within log_ now. https://codereview.chromium.org/953223002/diff/170002/remoting/webapp/crd/js/... File remoting/webapp/crd/js/server_log_entry.js (right): https://codereview.chromium.org/953223002/diff/170002/remoting/webapp/crd/js/... remoting/webapp/crd/js/server_log_entry.js:51: 'elapsed-time'; On 2015/02/27 02:24:46, Jamie wrote: > This will now all fit on one line. Done.
https://codereview.chromium.org/953223002/diff/250001/remoting/webapp/crd/js/... File remoting/webapp/crd/js/log_to_server.js (right): https://codereview.chromium.org/953223002/diff/250001/remoting/webapp/crd/js/... remoting/webapp/crd/js/log_to_server.js:28: this.sessionStartTime_ = 0; You need to initialize this to the current time. Also, please make sure that you don't see any significant time gap between the ctor and where the start time was previously being initialized. If it's more than a few milliseconds, then we'll see a discontinuity in our stats before and after landing this change.
Thanks Jamie. PTAL. https://codereview.chromium.org/953223002/diff/250001/remoting/webapp/crd/js/... File remoting/webapp/crd/js/log_to_server.js (right): https://codereview.chromium.org/953223002/diff/250001/remoting/webapp/crd/js/... remoting/webapp/crd/js/log_to_server.js:28: this.sessionStartTime_ = 0; On 2015/02/28 00:35:37, Jamie wrote: > You need to initialize this to the current time. Also, please make sure that you > don't see any significant time gap between the ctor and where the start time was > previously being initialized. If it's more than a few milliseconds, then we'll > see a discontinuity in our stats before and after landing this change. Done. I tested the additional time doing it here adds to subsequent elapsed time calculations, and noticed that we add about 200ms. This is just the 1st time I connected to a host. The next time, we added about 120-150ms. That seems a little high but should be acceptable. https://codereview.chromium.org/953223002/diff/270001/remoting/webapp/crd/js/... File remoting/webapp/crd/js/log_to_server.js (right): https://codereview.chromium.org/953223002/diff/270001/remoting/webapp/crd/js/... remoting/webapp/crd/js/log_to_server.js:149: (state == remoting.ClientSession.State.CONNECTED)); I think this function should be removed, now that we using this approach to calculate time-to-connect. Instead, just call isEndOfSession. WDYT? In fact, we could probably get rid of the session-duration field.
LGTM as long as the timestamps of signal strategy progress events isn't significantly affected by having a shared start timestamp for all logs. https://codereview.chromium.org/953223002/diff/270001/remoting/webapp/crd/js/... File remoting/webapp/crd/js/log_to_server.js (right): https://codereview.chromium.org/953223002/diff/270001/remoting/webapp/crd/js/... remoting/webapp/crd/js/log_to_server.js:149: (state == remoting.ClientSession.State.CONNECTED)); On 2015/02/28 01:20:27, anandc wrote: > I think this function should be removed, now that we using this approach to > calculate time-to-connect. Instead, just call isEndOfSession. > WDYT? > In fact, we could probably get rid of the session-duration field. Yes, the session duration field isn't buying us anything since it's basically the same as the elapsed time for that specific event.
Patchset #8 (id:290001) has been deleted
On 2015/02/28 01:52:34, Jamie wrote: > LGTM as long as the timestamps of signal strategy progress events isn't > significantly affected by having a shared start timestamp for all logs. > > https://codereview.chromium.org/953223002/diff/270001/remoting/webapp/crd/js/... > File remoting/webapp/crd/js/log_to_server.js (right): > > https://codereview.chromium.org/953223002/diff/270001/remoting/webapp/crd/js/... > remoting/webapp/crd/js/log_to_server.js:149: (state == > remoting.ClientSession.State.CONNECTED)); > On 2015/02/28 01:20:27, anandc wrote: > > I think this function should be removed, now that we using this approach to > > calculate time-to-connect. Instead, just call isEndOfSession. > > WDYT? > > In fact, we could probably get rid of the session-duration field. > > Yes, the session duration field isn't buying us anything since it's basically > the same as the elapsed time for that specific event. Confirmed that the timestamps of signal strategy progress are only impacted by about 1ms. Latest patch-set also removes the now unnecessary logging of session duration.
LGTM! Thanks for the cleanup, and don't forget the server-side changes :)
Patchset #9 (id:330001) has been deleted
The CQ bit was checked by anandc@chromium.org
CQ is trying da patch. Follow status at https://chromium-cq-status.appspot.com/patch-status/953223002/310001
The CQ bit was unchecked by commit-bot@chromium.org
Try jobs failed on following builders: ios_dbg_simulator_ninja on tryserver.chromium.mac (JOB_FAILED, http://build.chromium.org/p/tryserver.chromium.mac/builders/ios_dbg_simulator...)
The CQ bit was checked by anandc@chromium.org
CQ is trying da patch. Follow status at https://chromium-cq-status.appspot.com/patch-status/953223002/310001
The CQ bit was unchecked by commit-bot@chromium.org
Try jobs failed on following builders: ios_dbg_simulator_ninja on tryserver.chromium.mac (JOB_FAILED, http://build.chromium.org/p/tryserver.chromium.mac/builders/ios_dbg_simulator...)
The CQ bit was checked by anandc@chromium.org
CQ is trying da patch. Follow status at https://chromium-cq-status.appspot.com/patch-status/953223002/310001
Message was sent while issue was closed.
Committed patchset #8 (id:310001)
Message was sent while issue was closed.
Patchset 8 (id:??) landed as https://crrev.com/fcf59efc9dd11d746b0b8c8d26f34d41e94c5892 Cr-Commit-Position: refs/heads/master@{#318738} |
|||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
