Chromium Code Reviews
|
|
Chromium Code Reviews
Issue
1635903003:
[Devil] Add timeout to logcat record thread join. (Closed)
|
Created:
4 years, 11 months ago by mikecase (-- gone --) Modified:
4 years, 11 months ago Reviewers:
jbudorick CC:
catapult-reviews_chromium.org Base URL:
https://github.com/catapult-project/catapult.git@master Target Ref:
refs/heads/master Project:
catapult Visibility:
Public. |
Description[Devil] Add timeout to logcat record thread join.
Currently, the logcat monitor thread can hang if nothing is being
output by adb logcat after you try to join the recorder thread.
Adding timeout to join to prevent the thread from hanging for too long.
Committed: https://chromium.googlesource.com/external/github.com/catapult-project/catapult/+/030581d641bc56121c37b89f91bda25c4bc0b94f
Patch Set 1 #Patch Set 2 : #Patch Set 3 : Fix syntax error. #
Total comments: 2
Patch Set 4 : Add timeout to join. #
Total comments: 13
Patch Set 5 : #
Total comments: 6
Patch Set 6 : #Messages
Total messages: 21 (5 generated)
mikecase@chromium.org changed reviewers: + jbudorick@chromium.org
Do you have any ideas for a better solution than this. "for data in self._adb.Logcat" will block until either there is a new line of logcat data or the logcat process dies. I don't see a good way to kill the logcat process (although, if we could, that would probably be the best way to fix this). This is a pretty terribly solution since it could (probably unlikely?) cause the logcat monitor to be shutdown mid test if nothing is being logged. Also, it could still cause the main thread to be blocked for _LOGCAT_CMD_TIMEOUT seconds.
On 2016/01/26 at 19:13:31, mikecase wrote: > Do you have any ideas for a better solution than this. > > "for data in self._adb.Logcat" will block until either there is a new line of > logcat data or the logcat process dies. I don't see a good way to kill the logcat > process (although, if we could, that would probably be the best way to fix this). > > This is a pretty terribly solution since it could (probably unlikely?) cause the logcat monitor > to be shutdown mid test if nothing is being logged. Also, it could still cause the main thread to > be blocked for _LOGCAT_CMD_TIMEOUT seconds. Probably the best thing to do is ditch adb_wrapper.Logcat and just have the Popen object in logcat_monitor to fully control it?
On 2016/01/26 19:13:31, mikecase wrote: > Do you have any ideas for a better solution than this. I'll think about it. I don't think this is a viable solution as-is. > > "for data in self._adb.Logcat" will block until either there is a new line of > logcat data or the logcat process dies. I don't see a good way to kill the > logcat > process (although, if we could, that would probably be the best way to fix > this). > > This is a pretty terribly solution since it could (probably unlikely?) cause the s/could (probably unlikely?)/will definitely/ > logcat monitor > to be shutdown mid test if nothing is being logged. Also, it could still cause > the main thread to > be blocked for _LOGCAT_CMD_TIMEOUT seconds. That timeout you're setting isn't per line -- it's for the _entire_ iterable: https://code.google.com/p/chromium/codesearch#chromium/src/third_party/catapu...
On 2016/01/26 19:16:10, mikecase wrote: > On 2016/01/26 at 19:13:31, mikecase wrote: > > Do you have any ideas for a better solution than this. > > > > "for data in self._adb.Logcat" will block until either there is a new line of > > logcat data or the logcat process dies. I don't see a good way to kill the > logcat > > process (although, if we could, that would probably be the best way to fix > this). > > > > This is a pretty terribly solution since it could (probably unlikely?) cause > the logcat monitor > > to be shutdown mid test if nothing is being logged. Also, it could still cause > the main thread to > > be blocked for _LOGCAT_CMD_TIMEOUT seconds. > > Probably the best thing to do is ditch adb_wrapper.Logcat and just have the > Popen object in > logcat_monitor to fully control it? No, this is exactly what we want to discourage.
On 2016/01/26 at 19:18:41, jbudorick wrote: > On 2016/01/26 19:16:10, mikecase wrote: > > On 2016/01/26 at 19:13:31, mikecase wrote: > > > Do you have any ideas for a better solution than this. > > > > > > "for data in self._adb.Logcat" will block until either there is a new line of > > > logcat data or the logcat process dies. I don't see a good way to kill the > > logcat > > > process (although, if we could, that would probably be the best way to fix > > this). > > > > > > This is a pretty terribly solution since it could (probably unlikely?) cause > > the logcat monitor > > > to be shutdown mid test if nothing is being logged. Also, it could still cause > > the main thread to > > > be blocked for _LOGCAT_CMD_TIMEOUT seconds. > > > > Probably the best thing to do is ditch adb_wrapper.Logcat and just have the > > Popen object in > > logcat_monitor to fully control it? > > No, this is exactly what we want to discourage. Attempt 2 This isn't even that slow even though it looks like it would be super slow. After this change............. Remapping into /tmp/tmp9CghNc C 72.811s Main ******************************************************************************** C 72.812s Main Summary C 72.812s Main ******************************************************************************** C 72.812s Main [==========] 176 tests ran. C 72.812s Main [ PASSED ] 176 tests. C 72.812s Main ******************************************************************************** real 1m15.177s user 0m1.786s sys 0m0.859s Before this change................ Remapping into /tmp/tmp3mZcZb C 72.503s Main ******************************************************************************** C 72.503s Main Summary C 72.503s Main ******************************************************************************** C 72.503s Main [==========] 176 tests ran. C 72.503s Main [ PASSED ] 176 tests. C 72.504s Main ******************************************************************************** real 1m12.964s user 0m1.335s sys 0m0.657s So its not that much slower...
https://codereview.chromium.org/1635903003/diff/40001/devil/devil/android/log... File devil/devil/android/logcat_monitor.py (right): https://codereview.chromium.org/1635903003/diff/40001/devil/devil/android/log... devil/devil/android/logcat_monitor.py:160: @decorators.WithExplicitTimeoutAndRetries( This decorator is here to check a condition (whether the timeout has been hit) and kill the function's execution if that condition is met. In this case, it does so s.t. it can check another condition -- whether self._stop_recording_event is set -- and kill the loop if that condition is met. Why don't we skip the timeout portion and just have the supervising thread kill the generator thread if the event is set?
https://codereview.chromium.org/1635903003/diff/40001/devil/devil/android/log... File devil/devil/android/logcat_monitor.py (right): https://codereview.chromium.org/1635903003/diff/40001/devil/devil/android/log... devil/devil/android/logcat_monitor.py:160: @decorators.WithExplicitTimeoutAndRetries( On 2016/01/26 23:13:19, jbudorick wrote: > This decorator is here to check a condition (whether the timeout has been hit) > and kill the function's execution if that condition is met. In this case, it > does so s.t. it can check another condition -- whether > self._stop_recording_event is set -- and kill the loop if that condition is met. > > Why don't we skip the timeout portion and just have the supervising thread kill > the generator thread if the event is set? As for the slowness part, we could potentially add something to reraiser_thread s.t. we could run a generator in one thread and iterate over it in another. I think that could keep us from creating another thread on each logcat line.
I think this is a pretty good fix. PTAL https://codereview.chromium.org/1635903003/diff/60001/devil/devil/android/log... File devil/devil/android/logcat_monitor.py (right): https://codereview.chromium.org/1635903003/diff/60001/devil/devil/android/log... devil/devil/android/logcat_monitor.py:157: def record_to_file(): made record_to_file no longer open file since I no longer guarantee that it returns. https://codereview.chromium.org/1635903003/diff/60001/devil/devil/android/log... devil/devil/android/logcat_monitor.py:162: with self._record_file_lock: In the other place the lock is taken, _stop_recording_event is set and the file is closed. So file wont be closed unless _stop_recording_event is set. And inside this lock we don't write to the file if _stop_recording_event is set. So we are good. https://codereview.chromium.org/1635903003/diff/60001/devil/devil/android/log... devil/devil/android/logcat_monitor.py:189: self._record_file = tempfile.NamedTemporaryFile(mode='a', bufsize=1) bufsize=1 gives us the line buffering we had before. mode='a' is just so, in the rare occasion you might want to, you can Stop and then restart a logcat monitor and have it write to the same log.
race race race https://codereview.chromium.org/1635903003/diff/60001/devil/devil/android/log... File devil/devil/android/logcat_monitor.py (right): https://codereview.chromium.org/1635903003/diff/60001/devil/devil/android/log... devil/devil/android/logcat_monitor.py:165: self._record_file.write(data + '\n') This should now check that: - self._record_file is not None - self._record_file is open https://codereview.chromium.org/1635903003/diff/60001/devil/devil/android/log... devil/devil/android/logcat_monitor.py:175: with self._record_file_lock: This shouldn't actually be locking. It's not changing self._record_file. As is, record_to_file would always time out after setting the event while trying to acquire self._record_file_lock. https://codereview.chromium.org/1635903003/diff/60001/devil/devil/android/log... devil/devil/android/logcat_monitor.py:199: if self._record_file and self._output_file: You should acquire self._record_file_lock here now that you're using a timed join. https://codereview.chromium.org/1635903003/diff/60001/devil/devil/android/log... devil/devil/android/logcat_monitor.py:211: """ We should at least gracefully fail in the case where a user calls Close without calling Stop here. (or maybe just call stop if we're still recording) https://codereview.chromium.org/1635903003/diff/60001/devil/devil/android/log... devil/devil/android/logcat_monitor.py:212: if self._record_file: You should also acquire self._record_file_lock here for the same reason.
Description was changed from ========== [Devil] Add Logcat command timeout to logcat monitor. Currently, the logcat monitor thread can hang if nothing is being output by adb logcat after you try to join the recorder thread. Adding timeout to prevent the thread from hanging for too long. ========== to ========== [Devil] Add Logcat command timeout to logcat monitor. Currently, the logcat monitor thread can hang if nothing is being output by adb logcat after you try to join the recorder thread. Adding timeout to join to prevent the thread from hanging for too long. ==========
Description was changed from ========== [Devil] Add Logcat command timeout to logcat monitor. Currently, the logcat monitor thread can hang if nothing is being output by adb logcat after you try to join the recorder thread. Adding timeout to join to prevent the thread from hanging for too long. ========== to ========== [Devil] Add timeout to logcat record thread join. Currently, the logcat monitor thread can hang if nothing is being output by adb logcat after you try to join the recorder thread. Adding timeout to join to prevent the thread from hanging for too long. ==========
The join is no longer in a lock like you suggested. (which could have made join time out when it wouldn't otherwise) Added locks to where the file is written to and closed. https://codereview.chromium.org/1635903003/diff/60001/devil/devil/android/log... File devil/devil/android/logcat_monitor.py (right): https://codereview.chromium.org/1635903003/diff/60001/devil/devil/android/log... devil/devil/android/logcat_monitor.py:165: self._record_file.write(data + '\n') On 2016/01/27 at 16:17:37, jbudorick wrote: > This should now check that: > - self._record_file is not None > - self._record_file is open Done https://codereview.chromium.org/1635903003/diff/60001/devil/devil/android/log... devil/devil/android/logcat_monitor.py:175: with self._record_file_lock: On 2016/01/27 at 16:17:36, jbudorick wrote: > This shouldn't actually be locking. It's not changing self._record_file. > > As is, record_to_file would always time out after setting the event while trying to acquire self._record_file_lock. Done https://codereview.chromium.org/1635903003/diff/60001/devil/devil/android/log... devil/devil/android/logcat_monitor.py:199: if self._record_file and self._output_file: On 2016/01/27 at 16:17:37, jbudorick wrote: > You should acquire self._record_file_lock here now that you're using a timed join. Done https://codereview.chromium.org/1635903003/diff/60001/devil/devil/android/log... devil/devil/android/logcat_monitor.py:212: if self._record_file: On 2016/01/27 at 16:17:37, jbudorick wrote: > You should also acquire self._record_file_lock here for the same reason. Done https://codereview.chromium.org/1635903003/diff/60001/devil/devil/android/log... devil/devil/android/logcat_monitor.py:228: logging.warning('Need to call |Close| on the logcat monitor when done!') Added lock here too.
Are any of the logcat monitor tests affected by this? https://codereview.chromium.org/1635903003/diff/80001/devil/devil/android/log... File devil/devil/android/logcat_monitor.py (right): https://codereview.chromium.org/1635903003/diff/80001/devil/devil/android/log... devil/devil/android/logcat_monitor.py:200: with self._record_file_lock: move the if statement inside the lock https://codereview.chromium.org/1635903003/diff/80001/devil/devil/android/log... devil/devil/android/logcat_monitor.py:214: with self._record_file_lock: same https://codereview.chromium.org/1635903003/diff/80001/devil/devil/android/log... devil/devil/android/logcat_monitor.py:230: with self._record_file_lock: same
No tests are effected by this change. https://codereview.chromium.org/1635903003/diff/80001/devil/devil/android/log... File devil/devil/android/logcat_monitor.py (right): https://codereview.chromium.org/1635903003/diff/80001/devil/devil/android/log... devil/devil/android/logcat_monitor.py:200: with self._record_file_lock: On 2016/01/27 at 18:15:32, jbudorick wrote: > move the if statement inside the lock Done https://codereview.chromium.org/1635903003/diff/80001/devil/devil/android/log... devil/devil/android/logcat_monitor.py:214: with self._record_file_lock: On 2016/01/27 at 18:15:32, jbudorick wrote: > same Done https://codereview.chromium.org/1635903003/diff/80001/devil/devil/android/log... devil/devil/android/logcat_monitor.py:230: with self._record_file_lock: On 2016/01/27 at 18:15:32, jbudorick wrote: > same Done
lgtm
On 2016/01/27 18:32:40, jbudorick wrote: > lgtm be sure to port this to chromium plz
The CQ bit was checked by mikecase@chromium.org
CQ is trying da patch. Follow status at https://chromium-cq-status.appspot.com/patch-status/1635903003/100001 View timeline at https://chromium-cq-status.appspot.com/patch-timeline/1635903003/100001
Message was sent while issue was closed.
Description was changed from ========== [Devil] Add timeout to logcat record thread join. Currently, the logcat monitor thread can hang if nothing is being output by adb logcat after you try to join the recorder thread. Adding timeout to join to prevent the thread from hanging for too long. ========== to ========== [Devil] Add timeout to logcat record thread join. Currently, the logcat monitor thread can hang if nothing is being output by adb logcat after you try to join the recorder thread. Adding timeout to join to prevent the thread from hanging for too long. Committed: https://chromium.googlesource.com/external/github.com/catapult-project/catapu... ==========
Message was sent while issue was closed.
Committed patchset #6 (id:100001) as https://chromium.googlesource.com/external/github.com/catapult-project/catapu... |
