Tracing broadcast crashes GPU process with UnsatisfiedLinkError |
||||||||||||||||||||||||
Issue descriptionChrome Version: ToT 59.0.3068.0 + 2b4707869c4c04d0e32a10217eaf422a42f1c95b OS: Android What steps will reproduce the problem? (1) Open https://webvr.info/samples/03-vr-presentation.html (2) Click "Enter VR" (3) Do a trace from command line: $ build/android/adb_profile_chrome --browser chromium --time 2 What is the expected result? Trace is collected as usual What happens instead? GPU process crashes in TracingBroadcastReceiver.onReceive: https://cs.chromium.org/chromium/src/content/public/android/java/src/org/chromium/content/browser/TracingControllerAndroid.java?l=280 java.lang.UnsatisfiedLinkError: No implementation found for java.lang.String org.chromium.content.browser.TracingControllerAndroid.nativeGetDefaultCategories() (tried Java_org_chromium_content_browser_TracingControllerAndroid_nativeGetDefaultCategories and Java_org_chromium_content_browser_TracingControllerAndroid_nativeGetDefaultCategories__) I'm not sure what's different as far as tracing is concerned during VR presentation, but apparently the broadcast ends up being handled by the GPU process which doesn't have the necessary native libraries loaded. I've worked around it by adding a try..catch(java.lang.UnsatisfiedLinkError) block around the onReceive method.
,
Apr 12 2017
,
Apr 13 2017
,
Apr 13 2017
The one unusual thing I can think of for WebVR's use of the GL process is that it creates a separate context in the browser process via content::Compositor::CreateContextProvider as introduced in http://crrev.com/2731833002. See https://cs.chromium.org/chromium/src/chrome/browser/android/vr_shell/mailbox_to_surface_bridge.cc?q=mailboxtosurfa+package:%5Echromium$&l=206 . I was under the impression that this only creates a new IPC channel to the existing GPU process, is it possible that this has unexpected side effects?
,
Apr 13 2017
,
Apr 17 2017
In https://codereview.chromium.org/2809043005/#msg8, primiano@ wrote: >Also, hold on, how do we end up hitting >content/**browser**/TracingControllerAndroid.java in the GPU process in the >first place? It is included in content/public here: https://cs.chromium.org/chromium/src/content/public/android/java/src/org/chromium/content/app/ContentApplication.java?type=cs&q=TracingControllerAndroid&sq=package:chromium&l=14 This seems wrong, but I didn't find a path that would get it into the GPU process. However, the crashing process is started as org.chromium.content.app.PrivilegedProcessService0 as shown in the log above.
,
Apr 18 2017
> https://cs.chromium.org/chromium/src/content/public/android/java/src/org/chromium/content/app/ContentApplication.java?type=cs&q=TracingControllerAndroid&sq=package:chromium&l=14 That one seems to be just about the shell (i.e. that should really be the browser process). I can't see how that explains TracingControllerAndroid to be hit by the gpu pocess. > However, the crashing process is started as org.chromium.content.app.PrivilegedProcessService0 as shown in the log above. Well somebody should probably investigate this then instead of adding a blanket try...catch. It is possible that a more substantial bug is hiding under the hoods in the VR ap. Can you try adding an assert in the ctor of TracingControllerAndroid so we can see where that is instantiated from in the gpu process?
,
May 1 2017
,
May 23 2017
Since this crash seems to happen only in WebVR mode and not in VrShell mode, I'm suspecting it's related to the way WebVR establishes a GPU command buffer channel. For background, WebVR's MailboxToSurfaceBridge uses Android compositor's CreateContextProvider as introduced in https://codereview.chromium.org/2731833002 . It's possible we're the only users of this API call at this point, and that it's doing something strange. Call sequence: https://cs.chromium.org/chromium/src/chrome/browser/android/vr_shell/mailbox_to_surface_bridge.cc?type=cs&q=CreateContextProvider+package:%5Echromium$&l=207 https://cs.chromium.org/chromium/src/content/browser/renderer_host/compositor_impl_android.cc?type=cs&q=CreateContextProvider+package:%5Echromium$&l=393 This is just a hypothesis at this point, but I think it's the main GPU related code that is used in WebVR but not VrShell for 2D browsing.
,
May 23 2017
+khushalsagar, do you think it's possible that the new CreateContextProvider and its call to EstablishGPUChannel may be doing something weird that could break tracing? See previous comment.
,
May 23 2017
The path that this call uses is the same that the non-VR mode uses in Clank for creating a GPU command buffer.
,
May 26 2017
Here's what I'm seeing. When we start up, we have several ContentApplications created (seemingly a random number of them, but usually 2-3, sometimes 4 or more): 05-25 16:38:46.106 21029 21029 E cr_billorr: at org.chromium.content.app.ContentApplication.<init>(ContentApplication.java:33) 05-25 16:38:46.106 21029 21029 E cr_billorr: at org.chromium.content.app.ContentApplication.<init>(ContentApplication.java:27) 05-25 16:38:46.106 21029 21029 E cr_billorr: at org.chromium.chrome.browser.ChromeApplication.<init>(ChromeApplication.java:36) 05-25 16:38:46.106 21029 21029 E cr_billorr: at java.lang.Class.newInstance(Native Method) 05-25 16:38:46.106 21029 21029 E cr_billorr: at android.app.Instrumentation.newApplication(Instrumentation.java:1101) 05-25 16:38:46.106 21029 21029 E cr_billorr: at android.app.Instrumentation.newApplication(Instrumentation.java:1086) 05-25 16:38:46.106 21029 21029 E cr_billorr: at android.app.LoadedApk.makeApplication(LoadedApk.java:942) 05-25 16:38:46.106 21029 21029 E cr_billorr: at android.app.ActivityThread.handleBindApplication(ActivityThread.java:5764) 05-25 16:38:46.106 21029 21029 E cr_billorr: at android.app.ActivityThread.-wrap1(Unknown Source:0) 05-25 16:38:46.106 21029 21029 E cr_billorr: at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1661) 05-25 16:38:46.106 21029 21029 E cr_billorr: at android.os.Handler.dispatchMessage(Handler.java:105) 05-25 16:38:46.106 21029 21029 E cr_billorr: at android.os.Looper.loop(Looper.java:164) 05-25 16:38:46.106 21029 21029 E cr_billorr: at android.app.ActivityThread.main(ActivityThread.java:6540) 05-25 16:38:46.106 21029 21029 E cr_billorr: at java.lang.reflect.Method.invoke(Native Method) 05-25 16:38:46.106 21029 21029 E cr_billorr: at com.android.internal.os.Zygote$MethodAndArgsCaller.run(Zygote.java:240) 05-25 16:38:46.106 21029 21029 E cr_billorr: at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:767) These each handle an onCreate method call, and registers an onIdle callback. 05-25 16:38:46.113 21029 21029 E cr_billorr: at org.chromium.content.app.ContentApplication.onCreate(ContentApplication.java:46) 05-25 16:38:46.113 21029 21029 E cr_billorr: at org.chromium.chrome.browser.ChromeApplication.onCreate(ChromeApplication.java:63) 05-25 16:38:46.113 21029 21029 E cr_billorr: at android.app.Instrumentation.callApplicationOnCreate(Instrumentation.java:1118) 05-25 16:38:46.113 21029 21029 E cr_billorr: at android.app.ActivityThread.handleBindApplication(ActivityThread.java:5790) 05-25 16:38:46.113 21029 21029 E cr_billorr: at android.app.ActivityThread.-wrap1(Unknown Source:0) 05-25 16:38:46.113 21029 21029 E cr_billorr: at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1661) 05-25 16:38:46.113 21029 21029 E cr_billorr: at android.os.Handler.dispatchMessage(Handler.java:105) 05-25 16:38:46.113 21029 21029 E cr_billorr: at android.os.Looper.loop(Looper.java:164) 05-25 16:38:46.113 21029 21029 E cr_billorr: at android.app.ActivityThread.main(ActivityThread.java:6540) 05-25 16:38:46.113 21029 21029 E cr_billorr: at java.lang.reflect.Method.invoke(Native Method) 05-25 16:38:46.113 21029 21029 E cr_billorr: at com.android.internal.os.Zygote$MethodAndArgsCaller.run(Zygote.java:240) 05-25 16:38:46.113 21029 21029 E cr_billorr: at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:767) 0-1 of them actually have the idle callback called, which creates/initialized TracingControllerAndroid: 05-25 16:39:07.495 21051 21051 E cr_billorr: at org.chromium.content.browser.TracingControllerAndroid.<init>(TracingControllerAndroid.java:79) 05-25 16:39:07.495 21051 21051 E cr_billorr: at org.chromium.content.app.ContentApplication.getTracingController(ContentApplication.java:38) 05-25 16:39:07.495 21051 21051 E cr_billorr: at org.chromium.content.app.ContentApplication$1.queueIdle(ContentApplication.java:58) 05-25 16:39:07.495 21051 21051 E cr_billorr: at android.os.MessageQueue.next(MessageQueue.java:394) 05-25 16:39:07.495 21051 21051 E cr_billorr: at android.os.Looper.loop(Looper.java:142) 05-25 16:39:07.495 21051 21051 E cr_billorr: at android.app.ActivityThread.main(ActivityThread.java:6540) 05-25 16:39:07.495 21051 21051 E cr_billorr: at java.lang.reflect.Method.invoke(Native Method) 05-25 16:39:07.495 21051 21051 E cr_billorr: at com.android.internal.os.Zygote$MethodAndArgsCaller.run(Zygote.java:240) 05-25 16:39:07.495 21051 21051 E cr_billorr: at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:767) When we enter VR, the others have the idle callback called, so other TracingControllerAndroid's are initialized. I'm not yet sure why. Finally when I take the trace using the instructions Klaus added above, I'm hitting a DCHECK: 05-25 16:41:09.411 21051 21051 F chromium: [FATAL:sequenced_task_runner_handle.cc(54)] Check failed: pool. ... 05-25 16:41:09.412 21051 21051 F libc : Fatal signal 6 (SIGABRT), code -6 in tid 21051 (ileged_process0) 05-25 16:41:09.424 20824 21034 D RenderScript: Successfully queried cache dir: /data/user_de/0/org.chromium.chrome/code_cache 05-25 16:41:09.424 20824 21034 D RenderScript: Setting cache dir: /data/user_de/0/org.chromium.chrome/code_cache 05-25 16:41:09.511 21363 21363 I crash_dump32: obtaining output fd from tombstoned 05-25 16:41:09.512 735 735 I /system/bin/tombstoned: received crash request for pid 21051 05-25 16:41:09.514 21363 21363 I crash_dump32: performing dump of process 21051 (target tid = 21051) 05-25 16:41:09.515 21363 21363 F DEBUG : *** *** *** *** *** *** *** *** *** *** *** *** *** *** *** *** 05-25 16:41:09.516 21363 21363 F DEBUG : Build fingerprint: 'google/marlin/marlin:8.0.0/OPR1.170518.002/4024270:userdebug/dev-keys' 05-25 16:41:09.516 21363 21363 F DEBUG : Revision: '0' 05-25 16:41:09.516 21363 21363 F DEBUG : ABI: 'arm' 05-25 16:41:09.516 21363 21363 F DEBUG : pid: 21051, tid: 21051, name: ileged_process0 >>> org.chromium.chrome:privileged_process0 <<< 05-25 16:41:09.516 21363 21363 F DEBUG : signal 6 (SIGABRT), code -6 (SI_TKILL), fault addr -------- 05-25 16:41:09.518 21363 21363 F DEBUG : Abort message: '[FATAL:sequenced_task_runner_handle.cc(54)] Check failed: pool. 05-25 16:41:09.518 21363 21363 F DEBUG : #00 0xc8cdf687 /data/app/org.chromium.chrome-b0drBZXLyDcfbjoT6IqNIg==/lib/arm/libbase.cr.so+0x00095687 05-25 16:41:09.518 21363 21363 F DEBUG : #01 0xc8cf55f5 /data/app/org.chromium.chrome-b0drBZXLyDcfbjoT6IqNIg==/lib/arm/libbase.cr.so+0x000ab5f5 05-25 16:41:09.518 21363 21363 F DEBUG : #02 0xc8d3aa95 /data/app/org.chromium.chrome-b0drBZXLyDcfbjoT6IqNIg==/lib/arm/libbase.cr.so+0x000f0a95 05-25 16:41:09.518 21363 21363 F DEBUG : #03 0xc8d3daa9 /data/app/org.chromium.chrome-b0drBZXLyDcfbjoT6IqNIg==/lib/arm/libbase.cr.so+0x000f3aa9 05-25 16:41:09.518 21363 21363 F DEBUG : #04 0xc0f7a2f9 /da 05-25 16:41:09.518 21363 21363 F DEBUG : r0 00000000 r1 0000523b r2 00000006 r3 00000008 05-25 16:41:09.518 21363 21363 F DEBUG : r4 0000523b r5 0000523b r6 ffbb5da8 r7 0000010c 05-25 16:41:09.518 21363 21363 F DEBUG : r8 ffbb5e08 r9 ffbb5f1c sl c8dbbc04 fp ffbb6360 05-25 16:41:09.518 21363 21363 F DEBUG : ip 00000000 sp ffbb5d98 lr e696c4a7 pc e699ca7c cpsr 200f0010 05-25 16:41:09.528 21363 21363 F DEBUG : 05-25 16:41:09.528 21363 21363 F DEBUG : backtrace: 05-25 16:41:09.528 21363 21363 F DEBUG : #00 pc 0004aa7c /system/lib/libc.so (tgkill+12) 05-25 16:41:09.528 21363 21363 F DEBUG : #01 pc 0001a4a3 /system/lib/libc.so (abort+54) 05-25 16:41:09.528 21363 21363 F DEBUG : #02 pc 00095647 /data/app/org.chromium.chrome-b0drBZXLyDcfbjoT6IqNIg==/lib/arm/libbase.cr.so (_ZN4base5debug13BreakDebuggerEv+18) 05-25 16:41:09.528 21363 21363 F DEBUG : #03 pc 000ab85d /data/app/org.chromium.chrome-b0drBZXLyDcfbjoT6IqNIg==/lib/arm/libbase.cr.so (_ZN7logging10LogMessageD1Ev+840) 05-25 16:41:09.528 21363 21363 F DEBUG : #04 pc 000f0a93 /data/app/org.chromium.chrome-b0drBZXLyDcfbjoT6IqNIg==/lib/arm/libbase.cr.so (_ZN4base25SequencedTaskRunnerHandle3GetEv+262) 05-25 16:41:09.528 21363 21363 F DEBUG : #05 pc 000f3aa7 /data/app/org.chromium.chrome-b0drBZXLyDcfbjoT6IqNIg==/lib/arm/libbase.cr.so (_ZN4base19SequencedWorkerPoolC2EjRKNSt6__ndk112basic_stringIcNS1_11char_traitsIcEENS1_9allocatorIcEEEENS_12TaskPriorityE+34) 05-25 16:41:09.528 21363 21363 F DEBUG : #06 pc 007db2f7 /data/app/org.chromium.chrome-b0drBZXLyDcfbjoT6IqNIg==/lib/arm/libcontent.cr.so 05-25 16:41:09.528 21363 21363 F DEBUG : #07 pc 007dc42b /data/app/org.chromium.chrome-b0drBZXLyDcfbjoT6IqNIg==/lib/arm/libcontent.cr.so (_ZN7content13BrowserThread11CurrentlyOnENS0_2IDE+22) 05-25 16:41:09.528 21363 21363 F DEBUG : #08 pc 00a5a66d /data/app/org.chromium.chrome-b0drBZXLyDcfbjoT6IqNIg==/lib/arm/libcontent.cr.so 05-25 16:41:09.529 21363 21363 F DEBUG : #09 pc 00aa39af /data/app/org.chromium.chrome-b0drBZXLyDcfbjoT6IqNIg==/lib/arm/libcontent.cr.so 05-25 16:41:09.529 21363 21363 F DEBUG : #10 pc 00aa3a75 /data/app/org.chromium.chrome-b0drBZXLyDcfbjoT6IqNIg==/lib/arm/libcontent.cr.so (Java_org_chromium_content_browser_TracingControllerAndroid_nativeStartTracing+132) 05-25 16:41:09.529 21363 21363 F DEBUG : #11 pc 000791d9 /data/app/org.chromium.chrome-b0drBZXLyDcfbjoT6IqNIg==/oat/arm/base.odex (offset 0x48000) Two followup questions: * why do we have multiple (random number) of ContentApplication's being created? * why does starting vr trigger the idle callbacks?
,
May 26 2017
My understanding is that we have multiple ContentApplications (one per process), including gpu and renderer processes (however the different processes will host different activities/services). During initialization, these register an idle handler that performs the following code:
// Will retry if the native library has not been initialized.
if (!LibraryLoader.isInitialized()) return true;
try {
getTracingController().registerReceiver(ContentApplication.this);
} catch (SecurityException e) {
// Happens if the process is isolated. Ignore.
}
Typically, the library is loaded for the browser process, but not others the first time through. Vr somehow triggers the idle handler for the other processes to run again, hitting the exception.
The bug is that the getTracingController().registerReceiver(ContentApplication.this) seems to still partially initialize things, even when the rest of tracing isn't fully initialized/ready to handle tracing starting.
I don't believe the fact that idle callbacks are triggered again when VR is entered is relevant. In particular, I could repro the DCHECK by starting chrome, switching tabs, hitting the home button, going back to chrome (I did switch orientation, and navigate a few times, but don't think it is relevant).
,
May 26 2017
,
Jun 5 2017
+vollick@, you mentioned you know some tracing experts who may be able to help investigate this? As billorr@ said in comment #13, this seems to be a pre-existing issue and not VR specific after all, though we seem to trigger the problem more consistently from VR mode.
,
Jun 5 2017
Yep, I was wondering if chiniforooshan@ might have some advice.
,
Jun 6 2017
Ao, there are two tracing controllers in the app and both register broadcast receivers? If so, it does indeed look wrong. I can try to understand what's going on, but I'm not very familiar with that part of the code. +Xianzhu and Yaron (from https://codereview.chromium.org/26740005).
,
Jun 6 2017
(+dtrainer@ for the question about LibraryLoader.isInitialized()) I think it's correct to have multiple tracing controllers given that each process have only one. The problems seem that: 1. The idle handler is called more than once after the library is loaded, causing the receiver is registered more than once; 2. The receiver is called a) before the library is loaded or b) after the library is unloaded. I don't see any possibility of 2 a). For 2 b), is it possible that the application is being force-stopped for some reason and the receiver is called after the library is unloaded? Another speculation is about LibraryLoader.isInitialized(). dtrainor@, why does https://codereview.chromium.org/2804743002 use BrowserStartupController instead of LibraryLoader.isInitialized()?
,
Jun 7 2017
,
Jun 7 2017
,
Jun 16 2017
Not sure if this helps at all, but I'm still seeing crashes on stopping tracing even with the very hackish workaround from http://crrev.com/2809043005 (wrapping an exception handler) included. In the full log (attached), I see "privileged_process0" being launched and later killed with SIGSEGV. The log should contain the full history of this Chrome instance, does this help show any extra processes or libraries being launched/killed/reloaded? The "61.0.3132.0" library loading message is for the GVR library that's supposed to be loaded into the browser process. Some log excerpts included here, see the attachment for context. 06-15 17:03:35.274 907 28431 I ActivityManager: START u0 {act=android.intent.action.MAIN cat=[android.intent.category.LAUNCHER] flg=0x10200000 cmp=org.chromium.chrome/com.google.android.apps.chrome.Main bnds=[1134,1242][1410,1614]} from uid 10032 $ egrep 'PrivilegedProcess|20785' ~/Downloads/crash-on-stop-tracing.txt 06-15 17:04:13.320 907 6897 I ActivityManager: Start proc 20785:org.chromium.chrome:privileged_process0/u0a133 for service org.chromium.chrome/org.chromium.content.app.PrivilegedProcessService0 06-15 17:04:13.386 20785 20785 I cr_CommandLineInitUtil: Initializing command line from alternative file /data/local/tmp/chrome-command-line 06-15 17:04:13.390 20785 20785 I cr_ChildProcessService: Creating new ChildProcessService pid=20785 06-15 17:04:13.483 20785 20806 I cr_LibraryLoader: Time to load native libraries: 47 ms (timestamps 580-627) 06-15 17:04:13.484 20785 20806 I cr_LibraryLoader: Using linker: org.chromium.base.library_loader.ModernLinker 06-15 17:04:13.486 20785 20806 I chromium: [INFO:library_loader_hooks.cc(144)] Chromium logging enabled: level = -1, default verbosity = 1 06-15 17:04:13.487 20785 20806 I cr_LibraryLoader: Expected native library version number "61.0.3132.0", actual native library version number "61.0.3132.0" 06-15 17:04:13.498 20785 20806 I Adreno : QUALCOMM build : bd51b6f, Iceb07a594c 06-15 17:04:13.498 20785 20806 I Adreno : Build Date : 05/08/17 06-15 17:04:13.498 20785 20806 I Adreno : OpenGL ES Shader Compiler Version: EV031.17.00.01 06-15 17:04:13.498 20785 20806 I Adreno : Local Branch : O8A 06-15 17:04:13.498 20785 20806 I Adreno : Remote Branch : 06-15 17:04:13.498 20785 20806 I Adreno : Remote Branch : 06-15 17:04:13.498 20785 20806 I Adreno : Reconstruct Branch : 06-15 17:04:13.516 20785 20806 I Adreno : PFP: 0x005ff087, ME: 0x005ff063 06-15 17:04:13.601 20785 20806 W VideoCapabilities: Unrecognized profile 2130706433 for video/avc 06-15 17:04:13.601 20785 20806 W VideoCapabilities: Unrecognized profile 2130706434 for video/avc 06-15 17:04:13.688 20785 20806 I VideoCapabilities: Unsupported profile 4 for video/mp4v-es 06-15 17:04:13.906 20785 20806 V chromium: [VERBOSE1:gles2_cmd_decoder.cc(3373)] GL_OES_packed_depth_stencil supported. ... 06-15 17:04:19.285 20785 20806 E chromium: [ERROR:gles2_cmd_decoder.cc(9720)] [.Offscreen-For-WebGL-0xcab1d000]RENDER WARNING: texture bound to texture unit 0 is not renderable. It maybe non-power-of-2 and have incompatible texture filtering. 06-15 17:04:55.549 20785 20785 W chromium: [WARNING:tracing_controller_android.cc(47)] Logging performance trace to file 06-15 17:04:55.550 20785 20785 W chromium: [WARNING:trace_event_android.cc(37)] Failed to write buffer 'trace_event_clock_sync: parent_ts=15732.693470 06-15 17:04:55.550 20785 20785 W chromium: ' to /sys/kernel/debug/tracing/trace_marker: Bad file descriptor 06-15 17:04:55.551 20785 20785 I cr_TracingController: Profiler started: 06-15 17:04:57.549 20785 21336 D OpenGLRenderer: HWUI GL Pipeline 06-15 17:04:57.596 20785 21336 I OpenGLRenderer: Initialized EGL, version 1.4 06-15 17:04:57.597 20785 21336 D OpenGLRenderer: Swap behavior 2 06-15 17:04:58.712 20785 20785 F libc : Fatal signal 11 (SIGSEGV), code 1, fault addr 0x0 in tid 20785 (ileged_process0) 06-15 17:04:58.917 733 733 I /system/bin/tombstoned: received crash request for pid 20785 06-15 17:04:58.923 21358 21358 I crash_dump32: performing dump of process 20785 (target tid = 20785) 06-15 17:04:58.926 21358 21358 F DEBUG : pid: 20785, tid: 20785, name: ileged_process0 >>> org.chromium.chrome:privileged_process0 <<< 06-15 17:05:00.321 907 1447 I ActivityManager: Process org.chromium.chrome:privileged_process0 (pid 20785) has died: fore TOP 06-15 17:05:00.321 907 1447 W ActivityManager: Scheduling restart of crashed service org.chromium.chrome/org.chromium.content.app.PrivilegedProcessService0 in 1000ms 06-15 17:05:00.328 20722 20748 W cr_ChildProcessConn: onServiceDisconnected (crash or killed by oom): pid=20785 06-15 17:05:00.552 907 942 E zygote64: failed to kill 1 processes for processgroup 20785 06-15 17:05:00.613 20722 20722 W chromium: [WARNING:compositor_view.cc(255)] Child process disconnected (type=9) pid=20785) 06-15 17:05:00.630 580 580 I Zygote : Process 20785 exited due to signal (11) 06-15 17:05:00.662 907 26451 I ActivityManager: Start proc 21377:org.chromium.chrome:privileged_process1/u0a133 for service org.chromium.chrome/org.chromium.content.app.PrivilegedProcessService1 Decoded crash address: signal 11 (SIGSEGV), code 1 (SEGV_MAPERR), fault addr 0x0 r0 00000000 r1 31a741a5 r2 0000000a r3 00000000 r4 cb5913a9 r5 c8bb2120 r6 ffb10e08 r7 cb5b1e99 r8 00000000 r9 ffb10fe4 sl cb58f3ef fp ffb11118 ip 00000076 sp ffb10d78 lr cc4275e1 pc cc4275e2 Stack Trace: RELADDR FUNCTION FILE:LINE 0117a5e2 GenerateTracingMetadataDict /usr/local/google/home/klausw/chromium2/src/content/browser/tracing/tracing_controller_impl.cc:887 0117a129 StopTracing /usr/local/google/home/klausw/chromium2/src/content/browser/tracing/tracing_controller_impl.cc:314 011a29c7 StopTracing /usr/local/google/home/klausw/chromium2/src/content/browser/android/tracing_controller_android.cc:60 011a2951 Java_org_chromium_content_browser_TracingControllerAndroid_nativeStopTracing /usr/local/google/home/klausw/chromium2/src/out/Mono2/gen/content/public/android/content_jni_headers/content/jni/TracingControllerAndroid_jni.h:76 0007ec07 offset 0x45000 /data/app/org.chromium.chrome-4RqvhBMqdy3FLKpaJbmpXA==/oat/arm/base.odex
,
Jun 16 2017
Does https://www.chromium.org/developers/how-tos/trace-event-profiling-tool/recording-tracing-runs#TOC-Capture-a-trace-from-Chrome-on-Android-with-DevTools- work for you? If not, is the error the same as using adb_profile_chrome?
,
Jun 16 2017
To clarify, yes, the error I got in comment #21 was using the command line tool: $ build/android/adb_profile_chrome --browser chromium --time 3 Using the "trace" link from chrome://inspect/?tracing#devices works, I don't get a crash when I do that.
,
Jun 16 2017
Sorry for the delayed reply! @18: I actually think you're hitting 2.a! My understanding is (and I may be incorrect, adding tedchoc@ who gave me advice about the API) that the LibraryLoader.isInitialized() only means the native libraries have been loaded and the JNI hooks are done. It doesn't mean the browser process has been completely initialized yet. So you're probably calling down to native and crashing because none of the stuff we expect to just be there is actually there yet.
,
Jun 16 2017
dtrainor - I'm confused, how could the browser process not be completely initialized yet? In the scenarios I've been seeing, it's been running and rendering WebGL for ~40 seconds already at the time I'm taking the trace, so it would seem odd if it still hadn't finished initializing at the time. I found something potentially interesting in the logs from comment #21: Browser starts, browser process PID=20722: 06-15 17:04:12.643 907 1516 I ActivityManager: Start proc 20722:org.chromium.chrome/u0a133 for activity org.chromium.chrome/com.google.android.apps.chrome.Main Browser process PID=20722 initializes a native GL context for TID=20756. Note that the "Initialized EGL" message immediately follows the earlier Adreno logs: 06-15 17:04:13.128 20722 20756 D OpenGLRenderer: HWUI GL Pipeline 06-15 17:04:13.161 20722 20756 I Adreno : QUALCOMM build : bd51b6f, Iceb07a594c 06-15 17:04:13.161 20722 20756 I Adreno : Build Date : 05/08/17 06-15 17:04:13.161 20722 20756 I Adreno : OpenGL ES Shader Compiler Version: EV031.17.00.01 06-15 17:04:13.161 20722 20756 I Adreno : Local Branch : O8A 06-15 17:04:13.161 20722 20756 I Adreno : Remote Branch : 06-15 17:04:13.161 20722 20756 I Adreno : Remote Branch : 06-15 17:04:13.161 20722 20756 I Adreno : Reconstruct Branch : 06-15 17:04:13.173 20722 20756 I Adreno : PFP: 0x005ff087, ME: 0x005ff063 06-15 17:04:13.176 20722 20756 I OpenGLRenderer: Initialized EGL, version 1.4 06-15 17:04:13.177 20722 20756 D OpenGLRenderer: Swap behavior 2 GPU process starts with PID=20785: 06-15 17:04:13.320 907 6897 I ActivityManager: Start proc 20785:org.chromium.chrome:privileged_process0/u0a133 for service org.chromium.chrome/org.chromium.content.app.PrivilegedProcessService0 06-15 17:04:13.487 20785 20806 I cr_LibraryLoader: Expected native library version number "61.0.3132.0", actual native library version number "61.0.3132.0" 06-15 17:04:13.498 20785 20806 I Adreno : QUALCOMM build : bd51b6f, Iceb07a594c 06-15 17:04:13.498 20785 20806 I Adreno : Build Date : 05/08/17 06-15 17:04:13.498 20785 20806 I Adreno : OpenGL ES Shader Compiler Version: EV031.17.00.01 06-15 17:04:13.498 20785 20806 I Adreno : Local Branch : O8A 06-15 17:04:13.498 20785 20806 I Adreno : Remote Branch : 06-15 17:04:13.498 20785 20806 I Adreno : Remote Branch : 06-15 17:04:13.498 20785 20806 I Adreno : Reconstruct Branch : GPU process does stuff: 06-15 17:04:13.906 20785 20806 V chromium: [VERBOSE1:gles2_cmd_decoder.cc(3373)] GL_OES_packed_depth_stencil supported. Later, tracing starts for browser (PID=20722) and GPU process (PID=20785): 06-15 17:04:55.489 20722 20722 W chromium: [WARNING:tracing_controller_android.cc(47)] Logging performance trace to file 06-15 17:04:55.549 20785 20785 W chromium: [WARNING:tracing_controller_android.cc(47)] Logging performance trace to file Here's the odd thing. GPU process prints the "OpenGLRenderer: Initialized EGL, version 1.4" message shortly after tracing started, even though it's already been happily rendering for a while: 06-15 17:04:57.549 20785 21336 D OpenGLRenderer: HWUI GL Pipeline 06-15 17:04:57.596 20785 21336 I OpenGLRenderer: Initialized EGL, version 1.4 06-15 17:04:57.597 20785 21336 D OpenGLRenderer: Swap behavior 2 ... and the GPU process (PID=20785) crashes a second after that: 06-15 17:04:58.712 20785 20785 F libc : Fatal signal 11 (SIGSEGV), code 1, fault addr 0x0 in tid 20785 (ileged_process0) Does this match the theory of incomplete initialization?
,
Jun 19 2017
Ah wow I didn't realize it was up for that long. Sadly I'm not sure what the initialization path is for the GL context here.
,
Jun 19 2017
@dtrainor, some more details for the path are in comment #9, and in comment #11 khushalsagar@ said "The path that this call uses is the same that the non-VR mode uses in Clank for creating a GPU command buffer". So it shouldn't be an unusual path as such, but maybe the Clank usage is followed by other calls that complete the missing initialization steps that aren't being called yet when used for VR compositing?
,
Jul 5 2017
For WebVR, the context is created on GL thread instead of UI thread. Not sure if this is the root cause. You can probably apply this patch: https://codereview.chromium.org/2969153002/ and see if the problem still reproduce afterwards.
,
Jul 14 2017
klausw: The patch above has landed. Please see whether that solves the issue. If not, let's find an owner for M62.
,
Jul 15 2017
Still crashing using a ToT build (f554301a3f844613539ae835ec0fdfbbd78202ee as of Fri Jul 14 23:49:17 2017 +0000), but I'm not seeing a Java exception this time: 07-14 17:49:13.642 32573 32573 W chromium: [WARNING:tracing_controller_android.cc(47)] Logging performance trace to file 07-14 17:49:13.642 32573 32573 W chromium: [WARNING:trace_event_android.cc(37)] Failed to write buffer 'trace_event_clock_sync: parent_ts=6373.241376 07-14 17:49:13.642 32573 32573 W chromium: ' to /sys/kernel/debug/tracing/trace_marker: Bad file descriptor --------- beginning of crash 07-14 17:49:13.644 32573 32573 F libc : Fatal signal 11 (SIGSEGV), code 1, fault addr 0xc in tid 32573 (ileged_process0) 07-14 17:49:13.717 753 753 I crash_dump32: obtaining output fd from tombstoned 07-14 17:49:13.718 758 758 I /system/bin/tombstoned: received crash request for pid 32573 07-14 17:49:13.724 753 753 I crash_dump32: performing dump of process 32573 (target tid = 32573) 07-14 17:49:13.725 753 753 F DEBUG : *** *** *** *** *** *** *** *** *** *** *** *** *** *** *** *** 07-14 17:49:13.725 753 753 F DEBUG : Build fingerprint: 'google/marlin/marlin:8.0.0/OPR1.170623.011/4160747:userdebug/dev-keys' 07-14 17:49:13.725 753 753 F DEBUG : Revision: '0' 07-14 17:49:13.725 753 753 F DEBUG : ABI: 'arm' 07-14 17:49:13.726 753 753 F DEBUG : pid: 32573, tid: 32573, name: ileged_process0 >>> org.chromium.chrome:privileged_process0 <<< 07-14 17:49:13.726 753 753 F DEBUG : signal 11 (SIGSEGV), code 1 (SEGV_MAPERR), fault addr 0xc 07-14 17:49:13.726 753 753 F DEBUG : Cause: null pointer dereference 07-14 17:49:13.726 753 753 F DEBUG : r0 ff80a130 r1 ff80a178 r2 00000000 r3 00000001 07-14 17:49:13.726 753 753 F DEBUG : r4 cb118984 r5 00000000 r6 c735ecc0 r7 00000000 07-14 17:49:13.726 753 753 F DEBUG : r8 ff80a130 r9 00000000 sl 01c9c380 fp ff80a394 07-14 17:49:13.726 753 753 F DEBUG : ip c8996959 sp ff80a120 lr c83bc565 pc c83bc564 cpsr 60000030 07-14 17:49:13.729 753 753 F DEBUG : 07-14 17:49:13.729 753 753 F DEBUG : backtrace: 07-14 17:49:13.729 753 753 F DEBUG : #00 pc 0037d564 /data/app/org.chromium.chrome-GnGDuH5hjS6GOs1jdPGYSg==/base.apk (offset 0xe90000) 07-14 17:49:13.730 753 753 F DEBUG : #01 pc 00349469 /data/app/org.chromium.chrome-GnGDuH5hjS6GOs1jdPGYSg==/base.apk (offset 0xe90000) 07-14 17:49:13.730 753 753 F DEBUG : #02 pc 0119188b /data/app/org.chromium.chrome-GnGDuH5hjS6GOs1jdPGYSg==/base.apk (offset 0xe90000) 07-14 17:49:13.730 753 753 F DEBUG : #03 pc 011baa85 /data/app/org.chromium.chrome-GnGDuH5hjS6GOs1jdPGYSg==/base.apk (offset 0xe90000) 07-14 17:49:13.730 753 753 F DEBUG : #04 pc 011ba9f5 /data/app/org.chromium.chrome-GnGDuH5hjS6GOs1jdPGYSg==/base.apk (offset 0xe90000) 07-14 17:49:13.730 753 753 F DEBUG : #05 pc 000bacf1 /data/app/org.chromium.chrome-GnGDuH5hjS6GOs1jdPGYSg==/oat/arm/base.odex (offset 0x45000) 07-14 17:49:14.387 758 758 E /system/bin/tombstoned: Tombstone written to: /data/tombstones//tombstone_07 07-14 17:49:14.395 949 1021 I BootReceiver: Copying /data/tombstones/tombstone_07 to DropBox (SYSTEM_TOMBSTONE) 07-14 17:49:14.422 32511 32511 W chromium: [WARNING:tracing_controller_android.cc(47)] Logging performance trace to file 07-14 17:49:14.431 949 2116 I ActivityManager: Process org.chromium.chrome:privileged_process0 (pid 32573) has died: fore TOP 07-14 17:49:14.431 32511 32511 W chromium: [WARNING:trace_event_android.cc(37)] Failed to write buffer 'trace_event_clock_sync: parent_ts=6374.030465 07-14 17:49:14.431 32511 32511 W chromium: ' to /sys/kernel/debug/tracing/trace_marker: Bad file descriptor 07-14 17:49:14.432 949 2116 W ActivityManager: Scheduling restart of crashed service org.chromium.chrome/org.chromium.content.app.PrivilegedProcessService0 in 1000ms Decoded trace: Stack Trace: RELADDR FUNCTION FILE:LINE v------> std::__ndk1::unique_ptr<base::SequencedWorkerPool::Inner, std::__ndk1::default_delete<base::SequencedWorkerPool::Inner> >::operator->() const /usr/local/google/home/klausw/chromium2/src/third_party/android_tools/ndk/sources/cxx-stl/llvm-libc++/libcxx/include/memory:2608 v------> base::SequencedWorkerPool::PostDelayedSequencedWorkerTask(base::SequencedWorkerPool::SequenceToken, tracked_objects::Location const&, base::Callback<void (), (base::internal::CopyMode)0, (base::internal::RepeatMode)0>, base::TimeDelta) /usr/local/google/home/klausw/chromium2/src/base/threading/sequenced_worker_pool.cc:1571 0037d564 base::SequencedWorkerPool::PoolSequencedTaskRunner::PostDelayedTask(tracked_objects::Location const&, base::Callback<void (), (base::internal::CopyMode)0, (base::internal::RepeatMode)0>, base::TimeDelta) /usr/local/google/home/klausw/chromium2/src/base/threading/sequenced_worker_pool.cc:240 00349469 base::Timer::PostNewScheduledTask(base::TimeDelta) /usr/local/google/home/klausw/chromium2/src/base/timer/timer.cc:201 0119188b content::TracingControllerImpl::StartTracing(base::trace_event::TraceConfig const&, base::Callback<void (), (base::internal::CopyMode)1, (base::internal::RepeatMode)1> const&) /usr/local/google/home/klausw/chromium2/src/content/browser/tracing/tracing_controller_impl.cc:255 011baa85 content::TracingControllerAndroid::StartTracing(_JNIEnv*, base::android::JavaParamRef<_jobject*> const&, base::android::JavaParamRef<_jstring*> const&, base::android::JavaParamRef<_jstring*> const&) /usr/local/google/home/klausw/chromium2/src/content/browser/android/tracing_controller_android.cc:49 011ba9f5 Java_org_chromium_content_browser_TracingControllerAndroid_nativeStartTracing /usr/local/google/home/klausw/chromium2/src/out/Mono2/gen/content/public/android/content_jni_headers/content/jni/TracingControllerAndroid_jni.h:63 000bacf1 offset 0x45000 /data/app/org.chromium.chrome-GnGDuH5hjS6GOs1jdPGYSg==/oat/arm/base.odex
,
Jul 27 2017
,
Aug 11 2017
,
Sep 22 2017
Ehsan, could you please take a look?
,
Oct 5 2017
Re comment #18: excuse my unfamiliarity with the android code. Could you please explain why it is OK to have tracing controllers in processes other than the browser process? As far as I understand, TracingControllerAndroid.java talks with the native code tracing_controller_android.cc which forwards calls to TracingController::GetInstance(). I'm pretty sure that on the C++ side, tracing controller is only available (linked) to the browser process.
,
Oct 6 2017
So, I created a (speculative) fix CL, with my limited understanding of the clank code: https://chromium-review.googlesource.com/c/chromium/src/+/705758 Can someone let me know how I can build VR-enabled chrome and depoly it on a device? I built chromium without VR with my patch. The GPU process does not crash with adb_profile_chrome and the trace file looks OK.
,
Oct 6 2017
Current top-of-tree Chrome includes WebVR support for Android, so you shouldn't need any special build settings. Just for reference, here's how I usually build it: ffmpeg_branding = "Chrome" is_component_build = false is_debug = false is_official_build = true proprietary_codecs = true symbol_level = 1 target_cpu = "arm" target_os = "android" use_goma = true enable_resource_whitelist_generation = false To test, open a WebVR page such as https://webvr.info/samples/03-vr-presentation.html and press the "Enter VR" button. I tried this just now on a Pixel XL, and got a GPU crash with this command line: $ build/android/adb_profile_chrome --browser chromium --time 2 --atrace-categories=gfx,view,input,freq,sched,irq,workq A Daydream ready device isn't required, but you need to have Google VR Services on the phone. (Chrome should prompt you to install it if you don't.)
,
Nov 3 2017
Ehsan, any update on this? Let me know if you need help to test on a device.
,
Nov 3 2017
The fix in #35 works for me. I didn't land it since I didn't know how to verify it does not break anything in CastApplication and I'm a bit swamped with other work. I just added someone from the cast team to the CL. Meanwhile, you should be able to patch the CL to use tracing; please let me know if there is any issues.
,
Nov 4 2017
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/5e3127a5b92a14a0c83283d73bed03dbc63eb4c0 commit 5e3127a5b92a14a0c83283d73bed03dbc63eb4c0 Author: Ehsan Chiniforooshan <chiniforooshan@chromium.org> Date: Fri Nov 03 23:11:06 2017 Android: init TracingController only in browser Tested by deploying chromium with this patch on a device and verifying that the following command does not cause crashes while browsing the webvr.info page and successfully captures a trace file: build/android/adb_profile_chrome --browser chromium --time 2 Bug= 710591 Change-Id: I7d733c94511492350c8c08e584dfa8c594c6de6f Reviewed-on: https://chromium-review.googlesource.com/705758 Reviewed-by: Xianzhu Wang <wangxianzhu@chromium.org> Reviewed-by: Bo <boliu@chromium.org> Commit-Queue: Ehsan Chiniforooshan <chiniforooshan@chromium.org> Cr-Commit-Position: refs/heads/master@{#513948} [modify] https://crrev.com/5e3127a5b92a14a0c83283d73bed03dbc63eb4c0/content/public/android/java/src/org/chromium/content/app/ContentApplication.java [modify] https://crrev.com/5e3127a5b92a14a0c83283d73bed03dbc63eb4c0/content/public/android/java/src/org/chromium/content/browser/BrowserStartupController.java
,
Nov 6 2017
,
Nov 14 2017
Thank you! Works for me too in Chrome Canary 64.0.3266.0. |
||||||||||||||||||||||||
►
Sign in to add a comment |
||||||||||||||||||||||||
Comment 1 by klausw@chromium.org
, Apr 12 2017108 KB
108 KB View Download