1167230 - Crash on retrieving Gecko profile

Status: RESOLVED FIXED

(Core :: Gecko Profiler, defect)

Description

[Eugen Sawin [:esawin]]

Attachment: stack.txt

STR:
1. Install Gecko Profiler add-on.
2. Connect to Android device via USB.
3. Press "Analyze" in the add-on to retrieve the profile.

Expected: Profile is retrieved and displayed.
Actual: Fennec crashes (see stack trace), no profile is being retrieved.

Workaround: Removing mUniqueStacks.reset() in ThreadProfile::StreamJSON prevents the crash.

Comment 1

[Shu-yu Guo [:shu]]

Is this intermittent? And is it reproducible in an emulator?

Comment 2

[Victor Porof [:vporof][:vp]]

I got this (or something with the same symptoms) in the browser toolbox today. Couldn't reproduce.

Comment 3

[Eugen Sawin [:esawin]]

(In reply to PTO until 05/25 from comment #1)
> Is this intermittent? And is it reproducible in an emulator?

It is not intermittent and is reproducing on all Android devices I have tried. I haven't tested on an emulator.

Comment 4

[Shu-yu Guo [:shu]]

(In reply to Eugen Sawin [:esawin] from comment #3)
> (In reply to PTO until 05/25 from comment #1)
> > Is this intermittent? And is it reproducible in an emulator?
> 
> It is not intermittent and is reproducing on all Android devices I have
> tried. I haven't tested on an emulator.

Could you please try and see? I don't have an actual device handy. Thanks!

Comment 5

[Shu-yu Guo [:shu]]

Attachment: Use nsCString instead of std::string in FrameKey in the profiler.

I guess std::string isn't memmove-safe on Android. Switch to nsCString instead;
I've confirmed locally that nsCString doesn't crash.

Comment 7

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/1118d0695452

Comment 9

[Wilson Page [:wilsonpage]]

I just built b2g with inbound and the problem seems to still exist. I'm relatively new to building my own B2G so there is a chance I have done something wrong. Is anyone able to clarify this has actually made profiling devices via WebIDE-devtools possible?

Comment 10

[Brian Grinstead [:bgrins]]

Comment on attachment 8610944 [details] [diff] [review]
Use nsCString instead of std::string in FrameKey in the profiler.

Approval Request Comment
[Feature/regressing bug #]: 1167252, the new performance tool
[User impact if declined]: Won't ship the performance tool
[Describe test coverage new/current, TreeHerder]: There are try pushes in Bug 1167252 with all patches needing uplift
[Risks and why]: Requesting uplift for the accumulated changes in the performance tool since the 40 merge date, so these changes haven't had the full 6 weeks to bake.  Risks are generally contained within devtools, specifically within the performance panel.
[String/UUID change made/needed]: None

Comment 11

[Jordan Santell [:jsantell] [@jsantell]]

@wilsonpage wcosta confirmed this fixed the issue on B2G -- I suspect you may have had trouble with this as the patch has not yet made it's way to b2g-inbound. Not sure how often those get updated, but definitely keeping an eye out for this issue

Comment 12

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/1118d0695452

Comment 13

[Brian Grinstead [:bgrins]]

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

Comment 14

[Brian Grinstead [:bgrins]]

Note: I had verbal confirmation for these uplifts from Sylvestre even before he's flagged them as a+.  See https://bugzilla.mozilla.org/show_bug.cgi?id=1167252#c26

Comment 15

[Wilson Page [:wilsonpage]]

I just flashed m-c and the bug still exists.

VIDEO:

https://www.youtube.com/watch?v=-UWO-3_hrDQ

DEVICE VERSIONS:

Build ID               20150528010203
Gaia Revision          f84772d2640d825eaf3f9fcd906b4756e19e8a3f
Gaia Date              2015-05-26 12:47:07
Gecko Revision         https://hg.mozilla.org/mozilla-central/rev/baa9c64fea6f
Gecko Version          41.0a1
Device Name            flame
Firmware(Release)      4.4.2
Firmware(Incremental)  eng.cltbld.20150212.043653
Firmware Date          Thu Feb 12 04:37:04 EST 2015
Bootloader             L1TC000118D0

Comment 16

[Sylvestre Ledru [:Sylvestre]]

Comment on attachment 8610944 [details] [diff] [review]
Use nsCString instead of std::string in FrameKey in the profiler.

Change approved to skip one train as part of the spring campaign.

Comment 17

[Wander Lairson Costa]

(In reply to Wilson Page [:wilsonpage] from comment #15)
> I just flashed m-c and the bug still exists.
> 
> VIDEO:
> 
> https://www.youtube.com/watch?v=-UWO-3_hrDQ
> 
> DEVICE VERSIONS:
> 
> Build ID               20150528010203
> Gaia Revision          f84772d2640d825eaf3f9fcd906b4756e19e8a3f
> Gaia Date              2015-05-26 12:47:07
> Gecko Revision        
> https://hg.mozilla.org/mozilla-central/rev/baa9c64fea6f
> Gecko Version          41.0a1
> Device Name            flame
> Firmware(Release)      4.4.2
> Firmware(Incremental)  eng.cltbld.20150212.043653
> Firmware Date          Thu Feb 12 04:37:04 EST 2015
> Bootloader             L1TC000118D0

Hi, can you confirm if you have this commit [1] in your repo?

[1] http://hg.mozilla.org/integration/b2g-inbound/rev/1118d0695452

Comment 18

[Wilson Page [:wilsonpage]]

(In reply to Wander Lairson Costa [:wcosta] from comment #17)
> (In reply to Wilson Page [:wilsonpage] from comment #15)
> > I just flashed m-c and the bug still exists.
> > 
> > VIDEO:
> > 
> > https://www.youtube.com/watch?v=-UWO-3_hrDQ
> > 
> > DEVICE VERSIONS:
> > 
> > Build ID               20150528010203
> > Gaia Revision          f84772d2640d825eaf3f9fcd906b4756e19e8a3f
> > Gaia Date              2015-05-26 12:47:07
> > Gecko Revision        
> > https://hg.mozilla.org/mozilla-central/rev/baa9c64fea6f
> > Gecko Version          41.0a1
> > Device Name            flame
> > Firmware(Release)      4.4.2
> > Firmware(Incremental)  eng.cltbld.20150212.043653
> > Firmware Date          Thu Feb 12 04:37:04 EST 2015
> > Bootloader             L1TC000118D0
> 
> Hi, can you confirm if you have this commit [1] in your repo?
> 
> [1] http://hg.mozilla.org/integration/b2g-inbound/rev/1118d0695452

My device reports itself at Gecko revision baa9c64fea6f. From the m-c log, it appears this revision falls after revision 1118d0695452 (when this patch landed on m-c). If that is the case, then yes, my device does contain this commit :)

As discussed yesterday on IRC (and in comment 9), I flashed my device with mozilla-inbound which also contained this commit. Testing todays m-c B2G build clarified yesterday's findings.

Comment 19

[Shu-yu Guo [:shu]]

(In reply to Wilson Page [:wilsonpage] from comment #18)
> 
> My device reports itself at Gecko revision baa9c64fea6f. From the m-c log,
> it appears this revision falls after revision 1118d0695452 (when this patch
> landed on m-c). If that is the case, then yes, my device does contain this
> commit :)
> 
> As discussed yesterday on IRC (and in comment 9), I flashed my device with
> mozilla-inbound which also contained this commit. Testing todays m-c B2G
> build clarified yesterday's findings.

Do you have a stack for the crash?

Comment 20

[Wilson Page [:wilsonpage]]

(In reply to Shu-yu Guo [:shu] from comment #19)
> (In reply to Wilson Page [:wilsonpage] from comment #18)
> > 
> > My device reports itself at Gecko revision baa9c64fea6f. From the m-c log,
> > it appears this revision falls after revision 1118d0695452 (when this patch
> > landed on m-c). If that is the case, then yes, my device does contain this
> > commit :)
> > 
> > As discussed yesterday on IRC (and in comment 9), I flashed my device with
> > mozilla-inbound which also contained this commit. Testing todays m-c B2G
> > build clarified yesterday's findings.
> 
> Do you have a stack for the crash?

I'm not familiar with retrieving crash dumps and couldn't seem to find the .dmp file following these instructions [1]. Although :wcosta has been able to reproduce, so he should be able to provide them.

[1] https://developer.mozilla.org/en-US/docs/Debugging_a_minidump

Comment 21

[Wander Lairson Costa]

I tried latest eng build in pvtbuild and indeed it crashes. I then cloned m-c, built and it doesn't crash, although I can't profile yet due to Bug 1168784. My only guess is that the build in pvtbuilds does not contain the fix yet.

Comment 22

[Jordan Santell [:jsantell] [@jsantell]]

(In reply to Wander Lairson Costa [:wcosta] from comment #21)
> I tried latest eng build in pvtbuild and indeed it crashes. I then cloned
> m-c, built and it doesn't crash, although I can't profile yet due to Bug
> 1168784. My only guess is that the build in pvtbuilds does not contain the
> fix yet.

You can use WebIDE and the devtools performance tool to record profiles on b2g without using the profile.sh script and gecko profiler, as well -- let me know if you need any help with recreating it via that

Comment 23

[Eric Rahm [:erahm]]

I've repro'd this w/ m-c and got a SIGBUS.

STR:
  1. Build against m-c (standard build)
  2. Launch clock
  3. Start profiling clock: |./profile.sh start -p 9030 -t Compositor,GeckoMain -f js,leaf,stackwalk -e 2000000 -i 1|
  4. Capture profile: |./profile.sh capture|
  5. Note clock crashes

In gdb:
> Program received signal SIGBUS, Bus error.
> operator[] (aIndex=1, this=0xb09b76e4) at /Users/ericrahm/dev/mozilla-central/tools/profiler/ProfileEntry.cpp:658
> 658             ProfileEntry readAheadEntry = mEntries[readAheadPos];

We believe this is due to unaligned access on ARM. As it turns out ProfileEntry is packed, so this does make some sense. Removing the |#pragma pack| clears up the sigbus for me.

Comment 24

[Eric Rahm [:erahm]]

Attachment: Don't pack ProfileEntry on ARM

Comment 25

[Shu-yu Guo [:shu]]

Comment on attachment 8612563 [details] [diff] [review]
Don't pack ProfileEntry on ARM

Review of attachment 8612563 [details] [diff] [review]:
-----------------------------------------------------------------

Thanks for the patch!

::: tools/profiler/ProfileEntry.h
@@ +24,5 @@
>  #include "mozilla/UniquePtr.h"
>  
>  class ThreadProfile;
>  
> +// NB: Packing this strucure has been shown to cause SIGBUS issues on ARM.

Nit: typo in structure

Comment 26

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/b65d8a1df422

Comment 27

[Markus Stange [:mstange]]

How come this wasn't a problem before?

Comment 28

[Shu-yu Guo [:shu]]

(In reply to Markus Stange [:mstange] from comment #27)
> How come this wasn't a problem before?

That's what I was wondering too, since it's been this way for 2 years? But indeed, without packing makes the SIGBUS go away.

Comment 29

[Shu-yu Guo [:shu]]

I suppose it's possible that my rewrite of profile streaming perturbed something such that GCC started generating different code?

Comment 30

[Markus Stange [:mstange]]

(In reply to Shu-yu Guo [:shu] from comment #29)
> I suppose it's possible that my rewrite of profile streaming perturbed
> something such that GCC started generating different code?

I guess... I can't come up with a better explanation.

Comment 31

[Wilson Page [:wilsonpage]]

Latest patch seems to fix crashes for me :)

Comment 32

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/b65d8a1df422

Comment 33

[Andrei Vaida [:avaida]]

I tried reproducing this issue using an Android 4.4.4 device via WebIDE, but each time I started recording from Desktop, a permanent hang would occur on the device. I'm pretty sure there's something wrong with my test environment.

Wilson, could you please confirm this fix on the latest Aurora [1] as well? I'd really appreciate it.


[1] https://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/latest-mozilla-aurora/

Comment 34

[Wilson Page [:wilsonpage]]

Devtools performance tool works for me in latest Aurora.

Comment 35

[Andrei Vaida [:avaida]]

(In reply to Wilson Page [:wilsonpage] from comment #34)
> Devtools performance tool works for me in latest Aurora.

Thanks a lot for helping out here! Setting status and flags accordingly.

Comment 36

[Benoit Girard (:BenWa)]

https://hg.mozilla.org/integration/mozilla-inbound/rev/ae84f9adafc7

Comment 37

[Benoit Girard (:BenWa)]

I removed this by accident, bug 1176263 tracked restoring it.

Comment 38

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/ae84f9adafc7

Comment 39

[Wilson Page [:wilsonpage]]

Reopening as symptoms have reappeared. I can no longer profile using devtools or ./profile.sh the latter crashes with:

~/B2G (master) $ ./profile.sh capture
Signaling Profiled Processes: 1612 16021
Stabilizing 1612 b2g ...
Pulling /data/local/tmp/profile_0_1612.txt into profile_1612_b2g.txt
Adding symbols to profile_1612_b2g.txt and creating profile_1612_b2g.sym ...
Traceback (most recent call last):
  File "./scripts/profile-symbolicate.py", line 495, in <module>
    main()
  File "./scripts/profile-symbolicate.py", line 460, in main
    profile = json.load(open(args.filename, "rb"))
  File "/usr/lib/python2.7/json/__init__.py", line 278, in load
    **kw)
  File "/usr/lib/python2.7/json/__init__.py", line 326, in loads
    return _default_decoder.decode(s)
  File "/usr/lib/python2.7/json/decoder.py", line 366, in decode
    obj, end = self.raw_decode(s, idx=_w(s, 0).end())
  File "/usr/lib/python2.7/json/decoder.py", line 382, in raw_decode
    obj, end = self.scan_once(s, idx)
ValueError: Unterminated string starting at: line 1 column 184310 (char 184310)
Stabilizing 16021 Contacts protot ...
Pulling /data/local/tmp/profile_2_16021.txt into profile_16021_Contactsprotot.txt
Adding symbols to profile_16021_Contactsprotot.txt and creating profile_16021_Contactsprotot.sym ...
Traceback (most recent call last):
  File "./scripts/profile-symbolicate.py", line 495, in <module>
    main()
  File "./scripts/profile-symbolicate.py", line 460, in main
    profile = json.load(open(args.filename, "rb"))
  File "/usr/lib/python2.7/json/__init__.py", line 278, in load
    **kw)
  File "/usr/lib/python2.7/json/__init__.py", line 326, in loads
    return _default_decoder.decode(s)
  File "/usr/lib/python2.7/json/decoder.py", line 366, in decode
    obj, end = self.raw_decode(s, idx=_w(s, 0).end())
  File "/usr/lib/python2.7/json/decoder.py", line 382, in raw_decode
    obj, end = self.scan_once(s, idx)
ValueError: Unterminated string starting at: line 1 column 262141 (char 262141)
Merging profile:  profile_1612_b2g.sym profile_16021_Contactsprotot.sym
./gecko/tools/profiler/merge-profiles.py profile_1612_b2g.sym profile_16021_Contactsprotot.sym
Traceback (most recent call last):
  File "./gecko/tools/profiler/merge-profiles.py", line 107, in <module>
    MergeProfiles(sys.argv[1:])
  File "./gecko/tools/profiler/merge-profiles.py", line 32, in MergeProfiles
    fp = open(fname, "r")
IOError: [Errno 2] No such file or directory: 'profile_1612_b2g.sym'

Results: profile_captured.sym
Removing old profile files (from device) ... done

Comment 40

[Eric Rahm [:erahm]]

(In reply to Wilson Page [:wilsonpage] from comment #39)
> Reopening as symptoms have reappeared. I can no longer profile using
> devtools or ./profile.sh the latter crashes with:
> 
> ~/B2G (master) $ ./profile.sh capture
> Signaling Profiled Processes: 1612 16021
> Stabilizing 1612 b2g ...
> Pulling /data/local/tmp/profile_0_1612.txt into profile_1612_b2g.txt
> Adding symbols to profile_1612_b2g.txt and creating profile_1612_b2g.sym ...
> Traceback (most recent call last):
>   File "./scripts/profile-symbolicate.py", line 495, in <module>
>     main()
>   File "./scripts/profile-symbolicate.py", line 460, in main
>     profile = json.load(open(args.filename, "rb"))
>   File "/usr/lib/python2.7/json/__init__.py", line 278, in load
>     **kw)
>   File "/usr/lib/python2.7/json/__init__.py", line 326, in loads
>     return _default_decoder.decode(s)
>   File "/usr/lib/python2.7/json/decoder.py", line 366, in decode
>     obj, end = self.raw_decode(s, idx=_w(s, 0).end())
>   File "/usr/lib/python2.7/json/decoder.py", line 382, in raw_decode
>     obj, end = self.scan_once(s, idx)
> ValueError: Unterminated string starting at: line 1 column 184310 (char
> 184310)
> Stabilizing 16021 Contacts protot ...
> Pulling /data/local/tmp/profile_2_16021.txt into
> profile_16021_Contactsprotot.txt
> Adding symbols to profile_16021_Contactsprotot.txt and creating
> profile_16021_Contactsprotot.sym ...
> Traceback (most recent call last):
>   File "./scripts/profile-symbolicate.py", line 495, in <module>
>     main()
>   File "./scripts/profile-symbolicate.py", line 460, in main
>     profile = json.load(open(args.filename, "rb"))
>   File "/usr/lib/python2.7/json/__init__.py", line 278, in load
>     **kw)
>   File "/usr/lib/python2.7/json/__init__.py", line 326, in loads
>     return _default_decoder.decode(s)
>   File "/usr/lib/python2.7/json/decoder.py", line 366, in decode
>     obj, end = self.raw_decode(s, idx=_w(s, 0).end())
>   File "/usr/lib/python2.7/json/decoder.py", line 382, in raw_decode
>     obj, end = self.scan_once(s, idx)
> ValueError: Unterminated string starting at: line 1 column 262141 (char
> 262141)
> Merging profile:  profile_1612_b2g.sym profile_16021_Contactsprotot.sym
> ./gecko/tools/profiler/merge-profiles.py profile_1612_b2g.sym
> profile_16021_Contactsprotot.sym
> Traceback (most recent call last):
>   File "./gecko/tools/profiler/merge-profiles.py", line 107, in <module>
>     MergeProfiles(sys.argv[1:])
>   File "./gecko/tools/profiler/merge-profiles.py", line 32, in MergeProfiles
>     fp = open(fname, "r")
> IOError: [Errno 2] No such file or directory: 'profile_1612_b2g.sym'
> 
> Results: profile_captured.sym
> Removing old profile files (from device) ... done

Wilson, can you provide further details? What type of build are you testing, what date is it from, can you grab a snippet of |adb logcat| from when you call |profile.sh|?

Comment 41

[Wilson Page [:wilsonpage]]

Build: Yesterday's B2G build
Logcat: https://pastebin.mozilla.org/8838132

Comment 42

[Wilson Page [:wilsonpage]]

Comment 37 suggests this will be fixed when bug 1176263 lands.

Comment 43

[Eric Rahm [:erahm]]

(In reply to Wilson Page [:wilsonpage] from comment #41)
> Build: Yesterday's B2G build

So a pvt flame-kk m-c eng build?

(In reply to Wilson Page [:wilsonpage] from comment #42)
> Comment 37 suggests this will be fixed when bug 1176263 lands.

AFAICT that's been on m-c since 2015-06-24 [1].

[1] http://hg.mozilla.org/mozilla-central/rev/ae84f9adafc7 (look at the push date)

Comment 44

[James Willcox (:snorp) ([e-mail]) (he/him)]

We lost Shu's original patch to switch to nsCString. I cloned this to bug 1178961 to fix that.