Scan documentation update and stop scan bug fix #513
Conversation
cupakromer
force-pushed
the
scan-stop-notes
branch
from
997c86c to
c4371ea
Compare
davidgyoung
left a comment
davidgyoung
left a comment
There was a problem hiding this comment.
I think this looks right. Is there a test you have run that indicates the stop scan did not work as written before? I know it worked in my tests, despite not being written as intended, but it may have just been due to timing issues.
| /** | ||
| * methods for clients | ||
| */ | ||
| @MainThread |
There was a problem hiding this comment.
Is this annotation intended to be used this way? The docs say it is supposed to indicate that the method should only be called on the main thread, and I don't see why that would be true in this case. It seems to be intended for methods that manipulate the UI. In this case, I don't think there is anything wrong from calling on a worker thread. Perhaps a comment would be a better way to indicate that it is not necessarily run on a worker thread.
There was a problem hiding this comment.
The scanner classes are not thread safe. They are started / run from the beacon service which runs from the main thread. Additionally, in the scanner class mHandler is defined on the main looper. One of the deferred tasks which are queued on this handler call scanLeDevice. As things are right now, for all intents and purposes these methods need to run on the main thread.
While we could add this to the javadoc, the annotation documents this with the benefit of giving an extra hint to intellisense. Now if you write the following you'll get a lint warning/error depending on the IDE configuration:
mScanHandler.post(new Runnable() {
@WorkerThread
@Override
public void run() {
scanLeDevice(true);
}
}| LogManager.e(TAG, "No Bluetooth adapter. beaconService cannot scan."); | ||
| } | ||
| if (enable) { | ||
| if (enable && mScanningEnabled) { |
There was a problem hiding this comment.
Not 100% sure why we would not want to execute this block if mScanningEnabled is false
There was a problem hiding this comment.
Why would we want to allow a scan to begin after stop has already been called?
mScanningEnabled is the main "is this cycled scanner started or stopped" flag. It is only set in start and stop.
|
I've attached some detailed method / state traces for the lollipop scanner as follows:
|
|
What difference should I see in these traces? For both the Before PR and PR files I see that scanning stops after STOP REQUESTED is annotated in the log, and there are no further scan starts. |
This helps to try explaining how / when the various internal handlers should be used. This is important to help developers understand various threading flow orders, race conditions, and resource contention problems. As part of the documentation this adds `MainThread` and `WorkerThread` annotations to the deferred `Runnable` tasks' `run` methods. See Also: - https://developer.android.com/studio/write/annotations.html#thread-annotations
This makes the current implicit assumption that the scan cycler is started/stopped on the main thread explicit. This helps quickly inform developers what the callback expectations are in regards to race conditions and state safety. In order to verify this we need to trace the `start`/`stop`/`destroy` calls back to the service. The service's core methods `onCreate` and `onDestroy` are called on the main thread (see links below). This means the service creates it's `mMessenger` on the main thread, which creates the `IncomingHandler` on the main thread which binds to the main looper. However, the `IncomingHandler` class itself leaves the looper unspecified relying on looper for the thread which creates it. As we did in #430, this modifies `IncomingHandler` to explicitly use the main looper as a future proofing mechanism. This way we can ensure this implicit expectation doesn't change or at least make it obvious when troubleshooting cases where someone expects it to have changed. Similarly, this adds the main thread annotation to it's `handleMessage` implementation. Working from here we can confirm that the only places where the beacon monitoring/ranging is updated is from the main thread through the `IncomingHandler`. As the `IncomingHandler` is the main communication channel for the service we transfer the main thread expectation to the associated ranging/monitoring methods. _If_ someone decides to call these methods directly on the service these annotations help the IDEs check/document that such calls are expected from the main thread. With all of that documented we can now confidently state that the scan cycler's `start`, `stop`, and `destroy` are also meant to be called from the main thread. As `start` and `stop` both call `scanLeDevice` we can start tracing any other threading expectations for it. We already know it's called from the main thread through deferred jobs. This leaves the `finishScanCycle` as the last call site. `finishScanCycle` is only called from `scheduleScanCycleStop`. As this method name implies it's called through a deferred job on the main thread. It is also called the "first" time in `scanLeDevice`. Thus we've shown that `scanLeDevice`, `finishScanCycle`, and `scheduleScanCycleStop` are expected to run on the main thread. See Also: - https://developer.android.com/reference/android/os/Handler.html#Handler%28%29 - https://developer.android.com/training/multiple-threads/communicate-ui.html - https://developer.android.com/reference/android/app/Service.html - https://developer.android.com/guide/components/services.html - #430
This fixes what I believe was a simply copy-paste error regarding how the scanner thread is quit. This uses the scanner thread handler, instead of the main thread handler, to schedule the `quit` operation. This way any queued scan jobs (such as a stop) complete before we quit the thread. This is what the comment states, but wasn't what the code implemented. The `mHandler.removeCallbacksAndMessages` is removed from the background job as `destroy` is already on the main thread. So we want to clear any other jobs still in the queue to run later now as we are in the process of destroying everything.
cupakromer
force-pushed
the
scan-stop-notes
branch
from
c4371ea to
0e2ca51
Compare
This adds a guard to ensure that we only attempt any further scans when the scan cycler is started. This helps ensure the cycler has terminated scanning for the case where all regions have been removed but the service is still bound. In this case only `stop` will be called (instead of both `stop` and `destroy`). When this happens there are two potential scheduled tasks still queued: - `scanLeDevice(true)` from `deferScanIfNeeded` - `scheduleScanCycleStop` Which potential task is queued is based on if we were in an active scan period or a between scan period when `stop` was called. In the case of a between scan period the `deferScanIfNeeded` _will_ cause a faux scanning cycle to start up again when it ends (scanning won't actually start, but all flags and internal state appear as if it is running). It will run for one more scan cycle before it terminates in `finishScanCycle`. Similarly, if we are in an active scan period the scheduled job for finishing the scan cycle will continue for the duration of the scan period.
Through testing it's been confirmed that the bluetooth scan callbacks are always run on the main thread. This chases that through the scanners and our callbacks so that this is properly documented / annotated. During this process the unused `AsyncTask` methods were removed as we don not use them. Additionally, the `mDistinctPacketsDetectedPerScan` flag has been declared `volatile` to ensure reads always see the most recently written value without having to rely on a heavy weight `synchronized` block. As this is a flag we only perform simple reads / writes. While we do perform a multi-step operation around reading/writing this value the work performed is too heavy weight and long to wrap it in a `synchronized` block. Using `volatile` gives multipel concurrent background threads a better chance of aborting this logic if another has changed the value. However, the downside of not having complete synchronization is that a background thread will try to check a few more packets and then re-set the flag to `true`.
cupakromer
force-pushed
the
scan-stop-notes
branch
from
0e2ca51 to
0f5e823
Compare
|
I've attached a new set of logs with more detailed annotations. I've also tried to better summarize the behavior in the chart here.
Essentially this PR stops extra unnecessary work being performed by background tasks. |
|
@davidgyoung I've added more annotated versions of the log files. I think these help demonstrate the behavior a bit better. |
|
Thanks for those tests, @cupakromer, those are helpful. I'm going to do some more testing with these changes combined with #484 before merging, as that provides a good test case for starting and stopping CycledLeScanner. |
|
Is this good to merge to |
|
Sorry, I haven't been able to run my tests yet on Android O because I had trouble with the build on my test device. I have the testing environment working now, so I will try to get the testing done tomorrow. |
|
Did a bunch of tests yesterday on both Android 6.0 and Android O with this PR merged into the scheduled-job-scanning branch. I started and stopped the CycledLeScanner 12+ on each platform times shifting from background to foreground and scanning stopped appropriately and the thread was killed. I also ran 32 10-second background scan cycles overnight on Android O and again saw scanning end appropriately. |
This is a follow up to #507
Bug Fix
Fix where scanner thread is quit
This fixes what I believe was a simply copy-paste error regarding how the scanner thread is quit. This uses the scanner thread handler, instead of the main thread handler, to schedule the
quitoperation. This way any queued scan jobs (such as a stop) complete before we quit the thread. This is what the comment states, but wasn't what the code implemented.Behavior Modification
Fix scan stop when bound but no monitored / ranged regions.
This adds a guard to ensure that we only attempt any further scans when the scan cycler is started. This helps ensure the cycler has terminated scanning for the case where all regions have been removed but the service is still bound. In this case only
stopwill be called (instead of bothstopanddestroy). When this happens there are two potential scheduled tasks still queued:scanLeDevice(true)fromdeferScanIfNeededscheduleScanCycleStopWhich potential task is queued is based on if we were in an active scan period or a between scan period when
stopwas called. In the case of a between scan period thedeferScanIfNeededwill cause a faux scanning cycle to start up again when it ends (scanning won't actually start, but all flags and internal state appear as if it is running). It will run for one more scan cycle before it terminates infinishScanCycle. Similarly, if we are in an active scan period the scheduled job for finishing the scan cycle will continue for the duration of the scan period.Documentation / Annotations
This helps to try explaining how / when the various internal handlers should be used. This is important to help developers understand various threading flow orders, race conditions, and resource contention problems. As part of the documentation this adds
MainThreadandWorkerThreadannotations to the deferredRunnabletasks'runmethods.This makes the current implicit assumption that the scan cycler is started/stopped on the main thread explicit. This helps quickly inform developers what the callback expectations are in regards to race conditions and state safety.
In order to verify this we need to trace the
start/stop/destroycalls back to the service. The service's core methodsonCreateandonDestroyare called on the main thread (see links below). This means the service creates it'smMessengeron the main thread, which creates theIncomingHandleron the main thread which binds to the main looper. However, theIncomingHandlerclass itself leaves the looper unspecified relying on looper for the thread which creates it.As we did in #430, this modifies
IncomingHandlerto explicitly use the main looper as a future proofing mechanism. This way we can ensure this implicit expectation doesn't change or at least make it obvious when troubleshooting cases where someone expects it to have changed. Similarly, this adds the main thread annotation to it'shandleMessageimplementation.Working from here we can confirm that the only places where the beacon monitoring/ranging is updated is from the main thread through the
IncomingHandler. As theIncomingHandleris the main communication channel for the service we transfer the main thread expectation to the associated ranging/monitoring methods. If someone decides to call these methods directly on the service these annotations help the IDEs check/document that such calls are expected from the main thread.With all of that documented we can now confidently state that the scan cycler's
start,stop, anddestroyare also meant to be called from the main thread. Asstartandstopboth callscanLeDevicewe can start tracing any other threading expectations for it. We already know it's called from the main thread through deferred jobs. This leaves thefinishScanCycleas the last call site.finishScanCycleis only called fromscheduleScanCycleStop. As this method name implies it's called through a deferred job on the main thread. It is also called the "first" time inscanLeDevice. Thus we've shown thatscanLeDevice,finishScanCycle, andscheduleScanCycleStopare expected to run on the main thread.See Also