Status Update
Comments
ch...@google.com <ch...@google.com>
vi...@google.com <vi...@google.com> #2
Android build
Which Android build are you using? (e.g. PPP5.180610.010)
Device used -- Device Make, Model, Android OS Version
Which device did you use to reproduce this issue?
Steps to reproduce (include sample app or apk if needed for reproduction)
What steps are needed to reproduce this issue?
Android full bug report (to be captured after reproducing the issue)
For steps to capture a bug report, please refer:
Screen record of the issue
Please capture screen record or video of the issue using following steps:
adb shell screenrecord /sdcard/video.mp4
Subsequently use following command to pull the recorded file:
adb pull /sdcard/video.mp4
Attach the file to this issue.
Note: Please avoid uploading directly to the issue using attachments. Please upload to google drive and share the folder to android-bugreport@google.com, then share the link here.
ch...@google.com <ch...@google.com> #3
I've added the problematic apk to /google/data/ro/teams/r8/bugs/b231903117
.
The issue reproduces on a Pixel (XL) device running Android 8:
$ adb shell cmd package compile -m speed-profile -f <package>
Failure: package <package> could not be compiled
Logcat:
05-10 14:33:28.301 958 4506 I PackageManager.DexOptimizer: Running dexopt (dexoptNeeded=-3) on: /data/app/<package>-GB48xq9ENBGnhSzzAGXlmg==/base.apk pkg=<package> isa=arm64 dexoptFlags=boot_complete,profile_guided,force target-filter=speed-profile oatDir=/data/app/<package>-GB48xq9ENBGnhSzzAGXlmg==/oat sharedLibraries=PCL[]
05-10 14:33:28.559 14663 14663 I dex2oat : /system/bin/dex2oat --input-vdex-fd=18 --output-vdex-fd=19 --compiler-filter=speed-profile --profile-file-fd=22 --classpath-dir=/data/app/<package>-GB48xq9ENBGnhSzzAGXlmg== --class-loader-context=PCL[]
05-10 14:33:41.546 10156 10222 I PhenotypeProcessReaper: Memory state is: 300
05-10 14:33:42.109 12446 14665 E memtrack: Couldn't load memtrack module
05-10 14:33:42.110 12446 14665 W android.os.Debug: failed to get memory consumption info: -1
05-10 14:33:42.743 12513 14666 E memtrack: Couldn't load memtrack module
05-10 14:33:42.743 12513 14666 W android.os.Debug: failed to get memory consumption info: -1
05-10 14:33:45.145 682 912 I nanohub : osLog: [AR_CHRE] IDLE => ON
05-10 14:33:46.794 12446 12491 I NetworkScheduler.Stats: Task com.google.android.gms/com.google.android.gms.checkin.CheckinService started execution. cause:4 exec_start_elapsed_seconds: 2944548 [CONTEXT service_id=218 ]
05-10 14:33:46.800 12446 14589 I NetworkScheduler.Stats: Task com.google.android.gms/com.google.android.gms.checkin.CheckinService finished executing. cause:4 result: 3 elapsed_millis: 47 uptime_millis: 47 exec_start_elapsed_seconds: 2944548 [CONTEXT service_id=218 ]
05-10 14:33:50.997 958 6870 D WificondControl: Scan result ready event
05-10 14:33:51.044 12446 14056 I ChimeraSrvcProxy: NullBinder for android.net.action.RECOMMEND_NETWORKS triggering remote TransactionTooLargeException due to Service without Chimera impl
05-10 14:34:03.410 682 912 I nanohub : osLog: [AR_CHRE] still: 100
05-10 14:34:03.412 682 912 I nanohub : osLog: [AR_CHRE] ON => IDLE
05-10 14:34:03.416 682 912 I nanohub : osLog: [AR_CHRE] IDLE => ON
05-10 14:34:07.700 958 968 I zygote64: Background concurrent copying GC freed 28118(18MB) AllocSpace objects, 30(600KB) LOS objects, 42% free, 26MB/46MB, paused 189us total 151.127ms
05-10 14:34:16.146 14663 14663 E libc++abi: terminating with uncaught exception of type std::bad_alloc: std::bad_alloc
05-10 14:34:16.146 14663 14663 F libc : Fatal signal 6 (SIGABRT), code -6 in tid 14663 (dex2oat), pid 14663 (dex2oat)
05-10 14:34:16.512 14672 14672 I crash_dump32: obtaining output fd from tombstoned, type: kDebuggerdTombstone
05-10 14:34:16.516 751 751 I /system/bin/tombstoned: received crash request for pid 14663
05-10 14:34:16.526 14672 14672 I crash_dump32: performing dump of process 14663 (target tid = 14663)
05-10 14:34:16.527 14672 14672 F DEBUG : *** *** *** *** *** *** *** *** *** *** *** *** *** *** *** ***
05-10 14:34:16.528 14672 14672 F DEBUG : Build fingerprint: 'google/marlin/marlin:8.1.0/OPM4.171019.021.P1/4820305:userdebug/dev-keys'
05-10 14:34:16.528 14672 14672 F DEBUG : Revision: '0'
05-10 14:34:16.528 14672 14672 F DEBUG : ABI: 'arm'
05-10 14:34:16.528 14672 14672 F DEBUG : pid: 14663, tid: 14663, name: dex2oat >>> /system/bin/dex2oat <<<
05-10 14:34:16.528 14672 14672 F DEBUG : signal 6 (SIGABRT), code -6 (SI_TKILL), fault addr --------
05-10 14:34:16.535 14672 14672 F DEBUG : Abort message: 'terminating with uncaught exception of type std::bad_alloc: std::bad_alloc'
05-10 14:34:16.535 14672 14672 F DEBUG : r0 00000000 r1 00003947 r2 00000006 r3 00000008
05-10 14:34:16.535 14672 14672 F DEBUG : r4 00003947 r5 00003947 r6 ffd9d65c r7 0000010c
05-10 14:34:16.535 14672 14672 F DEBUG : r8 00000000 r9 ffd9db18 sl ef77bfb3 fp 00000001
05-10 14:34:16.535 14672 14672 F DEBUG : ip 8f8f4550 sp ffd9d648 lr f29e4bdf pc f29de5ec cpsr 200f0030
05-10 14:34:16.617 14672 14672 F DEBUG :
05-10 14:34:16.617 14672 14672 F DEBUG : backtrace:
05-10 14:34:16.618 14672 14672 F DEBUG : #00 pc 0001a5ec /system/lib/libc.so (abort+63)
05-10 14:34:16.618 14672 14672 F DEBUG : #01 pc 00032991 /system/lib/libc++.so (abort_message+84)
05-10 14:34:16.618 14672 14672 F DEBUG : #02 pc 00032b29 /system/lib/libc++.so (demangling_terminate_handler()+180)
05-10 14:34:16.618 14672 14672 F DEBUG : #03 pc 00045a6f /system/lib/libc++.so (_ZSt11__terminatePFvvE+2)
05-10 14:34:16.618 14672 14672 F DEBUG : #04 pc 0004523d /system/lib/libc++.so (__cxa_throw+92)
05-10 14:34:16.618 14672 14672 F DEBUG : #05 pc 00045bb9 /system/lib/libc++.so (operator new(unsigned int)+60)
05-10 14:34:16.618 14672 14672 F DEBUG : #06 pc 00015809 /system/lib/libart-dexlayout.so (_ZNSt3__16vectorINS_10unique_ptrIN3art6dex_ir12PositionInfoENS_14default_deleteIS4_EEEENS_9allocatorIS7_EEE21__push_back_slow_pathIS7_EEvOT_+70)
05-10 14:34:16.618 14672 14672 F DEBUG : #07 pc 000146a1 /system/lib/libart-dexlayout.so (art::dex_ir::GetPositionsCb(void*, art::DexFile::PositionInfo const&)+60)
05-10 14:34:16.618 14672 14672 F DEBUG : #08 pc 00140fe1 /system/lib/libart.so (art::DexFile::DecodeDebugPositionInfo(art::DexFile::CodeItem const*, bool (*)(void*, art::DexFile::PositionInfo const&), void*) const+552)
05-10 14:34:16.618 14672 14672 F DEBUG : #09 pc 0001455d /system/lib/libart-dexlayout.so (art::dex_ir::Collections::GenerateMethodItem(art::DexFile const&, art::ClassDataItemIterator&)+212)
05-10 14:34:16.618 14672 14672 F DEBUG : #10 pc 000132db /system/lib/libart-dexlayout.so (art::dex_ir::Collections::CreateClassData(art::DexFile const&, unsigned char const*, unsigned int)+662)
05-10 14:34:16.618 14672 14672 F DEBUG : #11 pc 00012b3f /system/lib/libart-dexlayout.so (art::dex_ir::Collections::CreateClassDef(art::DexFile const&, unsigned int)+182)
05-10 14:34:16.618 14672 14672 F DEBUG : #12 pc 00017b17 /system/lib/libart-dexlayout.so (art::dex_ir::DexIrBuilder(art::DexFile const&)+450)
05-10 14:34:16.618 14672 14672 F DEBUG : #13 pc 0000f26f /system/lib/libart-dexlayout.so (art::DexLayout::ProcessDexFile(char const*, art::DexFile const*, unsigned int)+14)
05-10 14:34:16.618 14672 14672 F DEBUG : #14 pc 00172383 /system/lib/libart-compiler.so (art::OatWriter::LayoutAndWriteDexFile(art::OutputStream*, art::OatWriter::OatDexFile*)+382)
05-10 14:34:16.618 14672 14672 F DEBUG : #15 pc 00171d7b /system/lib/libart-compiler.so (art::OatWriter::WriteDexFile(art::OutputStream*, unix_file::FdFile*, art::OatWriter::OatDexFile*, bool)+50)
05-10 14:34:16.618 14672 14672 F DEBUG : #16 pc 0016bf45 /system/lib/libart-compiler.so (_ZN3art9OatWriter20WriteAndOpenDexFilesEPN9unix_file6FdFileEPNS_12OutputStreamENS_14InstructionSetEPKNS_22InstructionSetFeaturesEPNS_7SafeMapINSt3__112basic_stringIcNSB_11char_traitsIcEENSB_9allocatorIcEEEESH_NSB_4lessISH_EENSF_INSB_4pairIKSH_SH_EEEEEEbbPNSB_10unique_ptrINS_6MemMapENSB_14default_deleteISR_EEEEPNSB_6vectorINSQ_IKNS_7DexFileENSS_ISY_EEEENSF_IS10_EEEE+412)
05-10 14:34:16.619 14672 14672 F DEBUG : #17 pc 0000b7bd /system/bin/dex2oat (art::Dex2Oat::Setup()+1672)
05-10 14:34:16.619 14672 14672 F DEBUG : #18 pc 00008177 /system/bin/dex2oat (main+518)
05-10 14:34:16.619 14672 14672 F DEBUG : #19 pc 0007a5b5 /system/lib/libc.so (__libc_init+48)
05-10 14:34:16.619 14672 14672 F DEBUG : #20 pc 00007e6c /system/bin/dex2oat (_start_main+92)
05-10 14:34:16.852 958 3868 W NativeCrashListener: Couldn't find ProcessRecord for pid 14663
05-10 14:34:16.853 751 751 W /system/bin/tombstoned: crash socket received short read of length 0 (expected 12)
05-10 14:34:16.856 958 1005 I BootReceiver: Copying /data/tombstones/tombstone_41 to DropBox (SYSTEM_TOMBSTONE)
05-10 14:34:16.884 958 999 W BroadcastQueue: Background execution not allowed: receiving Intent { act=android.intent.action.DROPBOX_ENTRY_ADDED flg=0x10 (has extras) } to com.google.android.gms/.stats.service.DropBoxEntryAddedReceiver
05-10 14:34:16.885 958 999 W BroadcastQueue: Background execution not allowed: receiving Intent { act=android.intent.action.DROPBOX_ENTRY_ADDED flg=0x10 (has extras) } to com.google.android.gms/.chimera.GmsIntentOperationService$PersistentTrustedReceiver
05-10 14:34:17.167 716 3651 E installed: DexInv: --- END '/data/app/<package>-GB48xq9ENBGnhSzzAGXlmg==/base.apk' --- status=0x0006, process failed
05-10 14:34:17.214 716 3651 E installd: Failed to dexopt (6)
05-10 14:34:17.217 958 4506 W PackageManager.DexOptimizer: Failed to dexopt
05-10 14:34:17.217 958 4506 W PackageManager.DexOptimizer: com.android.server.pm.Installer$InstallerException: android.os.ServiceSpecificException: Failed to dexopt (code 6)
05-10 14:34:17.217 958 4506 W PackageManager.DexOptimizer: at com.android.server.pm.Installer.dexopt(Installer.java:290)
05-10 14:34:17.217 958 4506 W PackageManager.DexOptimizer: at com.android.server.pm.PackageDexOptimizer.dexOptPath(PackageDexOptimizer.java:252)
05-10 14:34:17.217 958 4506 W PackageManager.DexOptimizer: at com.android.server.pm.PackageDexOptimizer.performDexOptLI(PackageDexOptimizer.java:203)
05-10 14:34:17.217 958 4506 W PackageManager.DexOptimizer: at com.android.server.pm.PackageDexOptimizer.performDexOpt(PackageDexOptimizer.java:125)
05-10 14:34:17.217 958 4506 W PackageManager.DexOptimizer: at com.android.server.pm.PackageManagerService.performDexOptInternalWithDependenciesLI(PackageManagerService.java:10151)
05-10 14:34:17.217 958 4506 W PackageManager.DexOptimizer: at com.android.server.pm.PackageManagerService.performDexOptInternal(PackageManagerService.java:10103)
05-10 14:34:17.217 958 4506 W PackageManager.DexOptimizer: at com.android.server.pm.PackageManagerService.performDexOptTraced(PackageManagerService.java:10081)
05-10 14:34:17.217 958 4506 W PackageManager.DexOptimizer: at com.android.server.pm.PackageManagerService.performDexOptWithStatus(PackageManagerService.java:10075)
05-10 14:34:17.217 958 4506 W PackageManager.DexOptimizer: at com.android.server.pm.PackageManagerService.performDexOpt(PackageManagerService.java:10063)
05-10 14:34:17.217 958 4506 W PackageManager.DexOptimizer: at com.android.server.pm.PackageManagerService.performDexOptMode(PackageManagerService.java:10032)
05-10 14:34:17.217 958 4506 W PackageManager.DexOptimizer: at com.android.server.pm.PackageManagerShellCommand.runCompile(PackageManagerShellCommand.java:489)
05-10 14:34:17.217 958 4506 W PackageManager.DexOptimizer: at com.android.server.pm.PackageManagerShellCommand.onCommand(PackageManagerShellCommand.java:124)
05-10 14:34:17.217 958 4506 W PackageManager.DexOptimizer: at android.os.ShellCommand.exec(ShellCommand.java:96)
05-10 14:34:17.217 958 4506 W PackageManager.DexOptimizer: at com.android.server.pm.PackageManagerService.onShellCommand(PackageManagerService.java:22602)
05-10 14:34:17.217 958 4506 W PackageManager.DexOptimizer: at android.os.Binder.shellCommand(Binder.java:594)
05-10 14:34:17.217 958 4506 W PackageManager.DexOptimizer: at android.os.Binder.onTransact(Binder.java:492)
05-10 14:34:17.217 958 4506 W PackageManager.DexOptimizer: at android.content.pm.IPackageManager$Stub.onTransact(IPackageManager.java:2658)
05-10 14:34:17.217 958 4506 W PackageManager.DexOptimizer: at com.android.server.pm.PackageManagerService.onTransact(PackageManagerService.java:3774)
05-10 14:34:17.217 958 4506 W PackageManager.DexOptimizer: at android.os.Binder.execTransact(Binder.java:697)
vi...@google.com <vi...@google.com> #4
We’ve shared this with our product and engineering teams and will continue to provide updates as more information becomes available.
ng...@google.com <ng...@google.com> #5
Can you reproduce this on newer Android releases?
The crash seems to show we're running out of native memory in dex2oat.
br...@snapchat.com <br...@snapchat.com> #6
I tested on Android 7, 8 and 9. It only occurred on 8.
ng...@google.com <ng...@google.com> #7
I think in Android O, you can indirectly disable dexlayout (the optimization that's crashing) by having the dex stored uncompressed in your APK. Can you try that and see if it reproduces?
br...@snapchat.com <br...@snapchat.com> #8
I think uncompressed DEX in APKs is Android 9+? I assume its using this setting:
I wonder if its possible that dexlayout
also crashes on newer OS versions, but the timing of when it gets triggered is different (e.g. only bg-dexopt) and not in manually triggered speed-profile
.
In this case, it's likely that the OOM is due to newer DebugInfo optimizations in R8 3.3 that are triggering this pathological case. Let me know if there is anything else I can share from my end. This seems to be last blocker for us upgrading to the new version.
sg...@google.com <sg...@google.com> #9
Nicholas:
Is the uncompressed DEX in APKs "silently" supported already from Android O (26) to not run dexlayout? The API that Benjamin links to, and the info on it
Banjaminn:
As you are currently using your own patched build of R8 you can easily turn off the DebugInfo optimization. In class com.android.tools.r8.utils.InternalOptions
change the implementation of canUseDexPc2PcAsDebugInformation
to always return false
.
public boolean canUseDexPc2PcAsDebugInformation() {
return false;
}
Is it possible for you to try is this makes a difference for this dex2oat issue?
ng...@google.com <ng...@google.com> #10
#9: I believe so yes, that uncompressed dex are supported since O.
br...@snapchat.com <br...@snapchat.com> #11
I tried both of these things in isolation: (1) create APK with uncompressed DEX (2) disable Pc2Pc debug info
Either applying (1) or (2) will fix the issue. Using (2), reduces the app size reduction of going from R8 3.2 to 3.3. Before we saw -1.3MB, now we only see -700KB.
ze...@google.com <ze...@google.com> #12
It is unfortunate if we need to give up on the pc2pc debug tables and the saving that it gives.
It is likely that dexlayout is iterating the entire debug info stream, and thus when all of the methods are sharing a single large stream this blows time/space. Could you confirm if this is the case Nicolas?
Assuming it is, it might be possible to introduce some duplication by ensuring the pc2pc debug info for a given method is constrained by it size (for example limit all methods with max-pc < X to point to a pc2pc debug info encoding of length X, where X would then be increasing size, say 2^n buckets).
ng...@google.com <ng...@google.com> #13
#12: unclear to me if that is the case, but yeah, you could have pushed dexlayout to its limit.
ze...@google.com <ze...@google.com> #14
Benjaminn: can you run experiments for this issue on our main branch or should I create a demo fix on the 3.3 branch for you to verify the effects?
br...@snapchat.com <br...@snapchat.com> #15
Demo fix on 3.3 is preferred
ze...@google.com <ze...@google.com> #16
I've uploaded a 3.3 branch CL to
You can adjust the defaults as noted in the CL description. The CL as it is has a 332 byte regression on the TiVi app, so the size regression should be pretty small. If you set either the smallpc or smallmembers value to a high point, ala max-int, then you should have the same behavior as without the CL.
ze...@google.com <ze...@google.com>
br...@snapchat.com <br...@snapchat.com> #17
The default values in the CL still lead to dex2oat
to fail. The app size hit is ~50-100KB.
ze...@google.com <ze...@google.com> #18
Thanks for the update. I'm working on a local reproduction now.
ze...@google.com <ze...@google.com> #19
A few quick status updates.
Looking at the 8.0/8.1 art branch it looks like the dexlayout process is expanding the debug info tables without consideration for sharing. Thus the OOM.
Building various variants of the application affects the compile time (negatively) and size (positively) on device. Some numbers from experiments where I've set a bound on the de-duplicated size allowed for using the shared pc2pc encoding:
threshold = 100
dex size = 60.792.532
vdex size = 67.773.442
dex2oat time = 28.665s
threshold = 10.000
dex size = 60.124.004
vdex size = 67104914
dex2oat time = 30.888s
threshold = 1.000.000
dex size = 59.780.312
vdex size = 66.761.222
dex2oat time = 41.358s
From these numbers it appears that the de-duplication cost is "only" a regression in the compilation time on device. The ondevice storage does not appear affected. The .art
and .odex
files for the app after compiler where unchanged in size. The sizes being:
151552 base.art
1602176 base.odex
One caveat is that I've only managed to reproduce the failure using the 3.3 clean branch. The above runs are using main with additions for the threshold setup. So one issue could be that the profile is not triggering the same in the two setups. I'm investigating the difference and may need to pull the changes from main back to 3.3 to confirm the above findings.
ze...@google.com <ze...@google.com> #20
There is a (partial) fix up in
The summary is that the max-pc for each encoding was incorrectly computed across all dex files. Maintining the per-file bound allows the speed-profile compile to succeed locally.
However, the compile time is very large still and we should avoid that too. Doing so in a follow up so the smallest fix can be backported easily to 3.3 and then we will need to discuss if we can improve the compile speed too.
ze...@google.com <ze...@google.com> #21
The partial fix is up for landing on the 3.3 branch:
Could you verify if that also resolves the issue on your end (although the dex2oat compile time still regresses, it should not OOM with it now).
This issue is still open as we need to fix the compile time regression too.
br...@snapchat.com <br...@snapchat.com> #22
dex2oat now runs successfully, but it took a significant amount of time on a Pixel XL running Android 8. I attached a screenshot of the dex2oat output on completion (~257s runtime).
br...@snapchat.com <br...@snapchat.com> #23
Also, it seems this only reduces effectiveness of app size optimizations by ~50-100KB, which is good to see.
ze...@google.com <ze...@google.com> #24
Thanks for confirming. Yes the dex2oat compile time regression is large and I have a fix in progress. The size after the partial fix should actually be smaller than before (eg, than the build that would fail dex2oat speed-profile compilation).
The next change will however increase size by about 60k for the local runs I've attempted on the provided dump, but the compile time regression of dex2oat should only be a few seconds. I'll post a link once I have the change up for review.
ze...@google.com <ze...@google.com> #26
Yes. I'll likely pick it over today. Wanted to make sure it stuck on main first :-)
ze...@google.com <ze...@google.com> #27
This has landed on 3.3. Let me know if you hit any more issues and thanks for reporting!
Description
Background
We have an internal performance test framework similar to Macrobenchmark that performs speed profile compilation after collecting some profile data before collecting performance data.
Issue
When calling
cmd package compile -m speed-profile
on our app, it appears thatdex2oat
hangs. After the initialdex2oat
invocation, I don't see any subsequent logging fromdex2oat
. Note, I'm connecting to this device remotely and some time after the speed profile request, the connection gets disconnected so I'm not exactly sure what's happening on device. If more info is needed, I can get this device physically and try and see if I can get more details.Also note, calling
cmd package compile reset
does not have this issue and runs without fail.The artifacts I'll be sharing for b/231900726 should also reproduce this issue.