819310 - Intermittent "talosError: 'Exception caught: java.lang.NullPointerException [browser_output.txt]'" in tcheckerboard at org.mozilla.fennec.FennecNativeDriver.stopCheckerboardRecording(FennecNativeDriver.java:226)

Status: RESOLVED FIXED

(Firefox for Android Graveyard :: General, defect)

Description

[Ed Morley [:emorley]]

Android Tegra 250 mozilla-inbound talos remote-trobocheck on 2012-12-04 16:11:55 PST for push 7e8069286526

slave: tegra-316

https://tbpl.mozilla.org/php/getParsedLog.php?id=17608910&tree=Mozilla-Inbound

{
FIRE PROC: ' "MOZ_CRASHREPORTER_SHUTDOWN=1,MOZ_CRASHREPORTER_NO_REPORT=1,NO_EM_RESTART=1" am instrument -w -e deviceroot /mnt/sdcard/tests -e class org.mozilla.fennec.tests.testCheck org.mozilla.roboexample.test/org.mozilla.fennec.FennecInstrumentationTestRunner'
getting files in '/mnt/sdcard/tests/profile/minidumps/'
removing file: /mnt/sdcard/tests/browser_output.txt
NOISE: Exception caught during test!
NOISE: java.lang.NullPointerException
NOISE: 	at org.mozilla.fennec.FennecNativeDriver.stopCheckerboardRecording(FennecNativeDriver.java:226)
NOISE: 	at org.mozilla.fennec.tests.testCheck.testCheck(testCheck.java:51)
NOISE: 	at java.lang.reflect.Method.invokeNative(Native Method)
NOISE: 	at java.lang.reflect.Method.invoke(Method.java:521)
NOISE: 	at android.test.InstrumentationTestCase.runMethod(InstrumentationTestCase.java:204)
NOISE: 	at android.test.InstrumentationTestCase.runTest(InstrumentationTestCase.java:194)
NOISE: 	at android.test.ActivityInstrumentationTestCase2.runTest(ActivityInstrumentationTestCase2.java:186)
NOISE: 	at org.mozilla.fennec.tests.BaseTest.runTest(BaseTest.java:120)
NOISE: 	at junit.framework.TestCase.runBare(TestCase.java:127)
NOISE: 	at junit.framework.TestResult$1.protect(TestResult.java:106)
NOISE: 	at junit.framework.TestResult.runProtected(TestResult.java:124)
NOISE: 	at junit.framework.TestResult.run(TestResult.java:109)
NOISE: 	at junit.framework.TestCase.run(TestCase.java:118)
NOISE: 	at android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:169)
NOISE: 	at android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:154)
NOISE: 	at android.test.InstrumentationTestRunner.onStart(InstrumentationTestRunner.java:520)
NOISE: 	at android.app.Instrumentation$InstrumentationThread.run(Instrumentation.java:1447)
NOISE: __FAILException caught: java.lang.NullPointerException__FAIL
FIRE PROC: ' "MOZ_CRASHREPORTER_SHUTDOWN=1,MOZ_CRASHREPORTER_NO_REPORT=1,NO_EM_RESTART=1" am instrument -w -e deviceroot /mnt/sdcard/tests -e class org.mozilla.fennec.tests.testCheck org.mozilla.roboexample.test/org.mozilla.fennec.FennecInstrumentationTestRunner'
NOISE: Exception caught during test!
NOISE: java.lang.NullPointerException
NOISE: 	at org.mozilla.fennec.FennecNativeDriver.stopCheckerboardRecording(FennecNativeDriver.java:226)
NOISE: 	at org.mozilla.fennec.tests.testCheck.testCheck(testCheck.java:51)
NOISE: 	at java.lang.reflect.Method.invokeNative(Native Method)
NOISE: 	at java.lang.reflect.Method.invoke(Method.java:521)
NOISE: 	at android.test.InstrumentationTestCase.runMethod(InstrumentationTestCase.java:204)
NOISE: 	at android.test.InstrumentationTestCase.runTest(InstrumentationTestCase.java:194)
NOISE: 	at android.test.ActivityInstrumentationTestCase2.runTest(ActivityInstrumentationTestCase2.java:186)
NOISE: 	at org.mozilla.fennec.tests.BaseTest.runTest(BaseTest.java:120)
NOISE: 	at junit.framework.TestCase.runBare(TestCase.java:127)
NOISE: 	at junit.framework.TestResult$1.protect(TestResult.java:106)
NOISE: 	at junit.framework.TestResult.runProtected(TestResult.java:124)
NOISE: 	at junit.framework.TestResult.run(TestResult.java:109)
NOISE: 	at junit.framework.TestCase.run(TestCase.java:118)
NOISE: 	at android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:169)
NOISE: 	at android.test.AndroidTestRunner.runTest(AndroidTestRunner.java:154)
NOISE: 	at android.test.InstrumentationTestRunner.onStart(InstrumentationTestRunner.java:520)
NOISE: 	at android.app.Instrumentation$InstrumentationThread.run(Instrumentation.java:1447)
NOISE: __FAILException caught: java.lang.NullPointerException__FAIL
NOISE: __startBeforeLaunchTimestamp1354667029354__endBeforeLaunchTimestamp
NOISE: __startAfterTerminationTimestamp1354667096833__endAfterTerminationTimestamp
getting files in '/mnt/sdcard/tests/profile/minidumps/'
Failed tcheckerboard: 
		Stopped Tue, 04 Dec 2012 16:24:58
Traceback (most recent call last):
  File "run_tests.py", line 261, in run_tests
    talos_results.add(mytest.runTest(browser_config, test))
  File "/builds/tegra-316/talos-data/talos/ttest.py", line 387, in runTest
    test_results.add(browser_log_filename, counter_results=counter_results)
  File "/builds/tegra-316/talos-data/talos/results.py", line 120, in add
    browserLog = BrowserLogResults(filename=results, counter_results=counter_results, global_counters=self.global_counters)
  File "/builds/tegra-316/talos-data/talos/results.py", line 316, in __init__
    self.error(match.group(1))
  File "/builds/tegra-316/talos-data/talos/results.py", line 331, in error
    raise utils.talosError(message)
talosError: 'Exception caught: java.lang.NullPointerException [browser_output.txt]'
}

Comment 1

[Kartikaya Gupta (email:[e-mail])]

The only way I can see this happening intermittently is if the compositor thread is in the middle of recordCheckerboard() while the test thread calls stopCheckerboardRecording.

Cwiiis, this is a regression from bug 814437. The obvious fix is to add synchronized blocks but since we want recordCheckerboard() to run as fast as possible maybe the better solution is to just take the min of mCheckerboardAmounts.size() and mFrameTimes.size() and return that number of items from stopCheckerboardAmounts(). Also it might be better to move the mRecordingCheckerboard = false line up to before the size comparison to narrow the window of opportunity where this occurs.

Comment 2

[Chris Lord [:cwiiis]]

(In reply to Kartikaya Gupta (:kats) from comment #1)
> The only way I can see this happening intermittently is if the compositor
> thread is in the middle of recordCheckerboard() while the test thread calls
> stopCheckerboardRecording.
> 
> Cwiiis, this is a regression from bug 814437. The obvious fix is to add
> synchronized blocks but since we want recordCheckerboard() to run as fast as
> possible maybe the better solution is to just take the min of
> mCheckerboardAmounts.size() and mFrameTimes.size() and return that number of
> items from stopCheckerboardAmounts(). Also it might be better to move the
> mRecordingCheckerboard = false line up to before the size comparison to
> narrow the window of opportunity where this occurs.

Agreed on all accounts, patch incoming.

Comment 3

[Chris Lord [:cwiiis]]

Attachment: Fix checkerboard stop recording race

This makes it safe to call stopCheckerboardRecording while recordCheckerboard is executing. I also removed an extra unnecessary List get.

Comment 4

[Ed Morley [:emorley]]

Thank you for looking at this so quickly :-)

Comment 5

[Chris Lord [:cwiiis]]

Pushed to inbound: https://hg.mozilla.org/integration/mozilla-inbound/rev/781df25c776f

Comment 6

[Chris Lord [:cwiiis]]

Comment on attachment 689705 [details] [diff] [review]
Fix checkerboard stop recording race

[Approval Request Comment]
Bug caused by (feature/regressing bug #): Intermittent test failures
User impact if declined: Will make sheriff's lives harder :)
Testing completed (on m-c, etc.): Tested locally
Risk to taking this patch (and alternatives if risky): Low risk
String or UUID changes made by this patch: None

Somehow kats' review got lost (conflict?) - I have the email with the r+ and IRC confirmation though, so just marking it as such.

Also requesting for aurora, where this bug will exist since the low-precision tiles work merge.

Comment 7

[Kartikaya Gupta (email:[e-mail])]

(In reply to Chris Lord [:cwiiis] from comment #6)
> Somehow kats' review got lost (conflict?) - I have the email with the r+ and
> IRC confirmation though, so just marking it as such.

Yeah that was weird, apparently I closed my laptop while it was in the midst of submitting and so it didn't complete properly.

Comment 8

[Ed Morley [:emorley]]

(From a while back)
https://tbpl.mozilla.org/php/getParsedLog.php?id=17672531&tree=Mozilla-Inbound

Comment 9

[(no longer active)]

https://hg.mozilla.org/mozilla-central/rev/781df25c776f

Comment 10

[Lukas Blakk [:lsblakk] use ?needinfo]

Comment on attachment 689705 [details] [diff] [review]
Fix checkerboard stop recording race

low risk, test fix, approving.

Comment 11

[Kartikaya Gupta (email:[e-mail])]

Uplifting for Cwiiis since he's on vacation now.

https://hg.mozilla.org/releases/mozilla-aurora/rev/c4131283618f