search

felixge / pprofutils

MIT License
138 stars 17 forks source link

"Bad line" error on an Android simpleperf trace #3

Open mhansen opened 3 years ago

mhansen commented 3 years ago

Came across this trying to convert an android simpleperf trace to pprof:

I'll note the full repo steps here in case they're useful; they probably aren't though; the error message is probably sufficient:

$ git clone https://android.googlesource.com/platform/system/extras
$ cd extras/simpleperf/scripts
$ ./app_profiler.py -p com.google.android.apps.maps -r "-f 4000 -g -e cpu-clock --trace-offcpu --duration 60" --activity com.google.android.maps.MapsActivity --skip_collect_binaries
$ ./report_sample.py ~/simpleperf/perf.data | ~/FlameGraph/stackcollapse-perf.pl | ~/go/bin/text2pprof

Gives this error:

bad line: 6: "Binder:23281_1;__start_thread;__pthread_start;thread_data_t::trampoline;android::AndroidRuntime::javaThreadShell;android::Thread::_threadLoop;android::PoolThread::threadLoop;android::IPCThreadState::joinThreadPool;android::IPCThreadState::executeCommand;android::BBinder::transact;JavaBBinder::onTransact;_JNIEnv::CallBooleanMethod;art::JNI<false>::CallBooleanMethodV;art::JValue art::InvokeVirtualOrInterfaceWithVarArgs<art::ArtMethod*> 6"

This happens on line 6... let's look at the first 10 lines:

./report_sample.py ~/simpleperf/perf.data | ~/FlameGraph/stackcollapse-perf.pl | head
Binder:23281_1;__start_thread;__pthread_start;thread_data_t::trampoline;android::AndroidRuntime::javaThreadShell;android::Thread::_threadLoop;android::PoolThread::threadLoop;android::IPCThreadState::joinThreadPool 11
Binder:23281_1;__start_thread;__pthread_start;thread_data_t::trampoline;android::AndroidRuntime::javaThreadShell;android::Thread::_threadLoop;android::PoolThread::threadLoop;android::IPCThreadState::joinThreadPool;@plt 6
Binder:23281_1;__start_thread;__pthread_start;thread_data_t::trampoline;android::AndroidRuntime::javaThreadShell;android::Thread::_threadLoop;android::PoolThread::threadLoop;android::IPCThreadState::joinThreadPool;@plt;work_pending;do_notify_resume;__schedule;__schedule 3
Binder:23281_1;__start_thread;__pthread_start;thread_data_t::trampoline;android::AndroidRuntime::javaThreadShell;android::Thread::_threadLoop;android::PoolThread::threadLoop;android::IPCThreadState::joinThreadPool;android::IPCThreadState::executeCommand 10
Binder:23281_1;__start_thread;__pthread_start;thread_data_t::trampoline;android::AndroidRuntime::javaThreadShell;android::Thread::_threadLoop;android::PoolThread::threadLoop;android::IPCThreadState::joinThreadPool;android::IPCThreadState::executeCommand;android::BBinder::transact 1
Binder:23281_1;__start_thread;__pthread_start;thread_data_t::trampoline;android::AndroidRuntime::javaThreadShell;android::Thread::_threadLoop;android::PoolThread::threadLoop;android::IPCThreadState::joinThreadPool;android::IPCThreadState::executeCommand;android::BBinder::transact;JavaBBinder::onTransact;_JNIEnv::CallBooleanMethod;art::JNI<false>::CallBooleanMethodV 2
Binder:23281_1;__start_thread;__pthread_start;thread_data_t::trampoline;android::AndroidRuntime::javaThreadShell;android::Thread::_threadLoop;android::PoolThread::threadLoop;android::IPCThreadState::joinThreadPool;android::IPCThreadState::executeCommand;android::BBinder::transact;JavaBBinder::onTransact;_JNIEnv::CallBooleanMethod;art::JNI<false>::CallBooleanMethodV;art::JValue art::InvokeVirtualOrInterfaceWithVarArgs<art::ArtMethod*> 6
Binder:23281_1;__start_thread;__pthread_start;thread_data_t::trampoline;android::AndroidRuntime::javaThreadShell;android::Thread::_threadLoop;android::PoolThread::threadLoop;android::IPCThreadState::joinThreadPool;android::IPCThreadState::executeCommand;android::BBinder::transact;JavaBBinder::onTransact;_JNIEnv::CallBooleanMethod;art::JNI<false>::CallBooleanMethodV;art::JValue art::InvokeVirtualOrInterfaceWithVarArgs<art::ArtMethod*>;art_quick_invoke_stub;android.os.Binder.execTransact 2
Binder:23281_1;__start_thread;__pthread_start;thread_data_t::trampoline;android::AndroidRuntime::javaThreadShell;android::Thread::_threadLoop;android::PoolThread::threadLoop;android::IPCThreadState::joinThreadPool;android::IPCThreadState::executeCommand;android::BBinder::transact;JavaBBinder::onTransact;_JNIEnv::CallBooleanMethod;art::JNI<false>::CallBooleanMethodV;art::JValue art::InvokeVirtualOrInterfaceWithVarArgs<art::ArtMethod*>;art_quick_invoke_stub;android.os.Binder.execTransact;android.os.Binder.execTransactInternal 2
Binder:23281_1;__start_thread;__pthread_start;thread_data_t::trampoline;android::AndroidRuntime::javaThreadShell;android::Thread::_threadLoop;android::PoolThread::threadLoop;android::IPCThreadState::joinThreadPool;android::IPCThreadState::executeCommand;android::BBinder::transact;JavaBBinder::onTransact;_JNIEnv::CallBooleanMethod;art::JNI<false>::CallBooleanMethodV;art::JValue art::InvokeVirtualOrInterfaceWithVarArgs<art::ArtMethod*>;art_quick_invoke_stub;android.os.Binder.execTransact;android.os.Binder.execTransactInternal;ExecuteNterpImpl 1

At a guess, I'd say the problem is probably the space in between JValue art.

It's very possible that I'm holding this wrong and there shouldn't be spaces in these lines according to the format? However perhaps there is a way to 'greedily' consume forward till we get to the numbers, perhaps?

mhansen commented 3 years ago

To see the original input in-situ, here's a full perf sample in perf script format:

com.google.android.apps.maps    23281/23281 [007] 520295.965190: 244011 cpu-clock:
      75ddf8d7ce erb.kz (/data/app/~~9YPINW14y2izqCbN0YZR6A==/com.google.android.apps.maps-WZHISLiw8lkQTFvs8_mhPw==/oat/arm64/base.vdex)
      75ddf8840e erb.<init> (/data/app/~~9YPINW14y2izqCbN0YZR6A==/com.google.android.apps.maps-WZHISLiw8lkQTFvs8_mhPw==/oat/arm64/base.vdex)
      75db795620 java.lang.Object apnz.p() (/data/app/~~9YPINW14y2izqCbN0YZR6A==/com.google.android.apps.maps-WZHISLiw8lkQTFvs8_mhPw==/oat/arm64/base.odex)
      75dd0cb474 dav ere.h() (/data/app/~~9YPINW14y2izqCbN0YZR6A==/com.google.android.apps.maps-WZHISLiw8lkQTFvs8_mhPw==/oat/arm64/base.odex)
      75dcebc54c void dbk.c() (/data/app/~~9YPINW14y2izqCbN0YZR6A==/com.google.android.apps.maps-WZHISLiw8lkQTFvs8_mhPw==/oat/arm64/base.odex)
      75dd0667ec void ern.c() (/data/app/~~9YPINW14y2izqCbN0YZR6A==/com.google.android.apps.maps-WZHISLiw8lkQTFvs8_mhPw==/oat/arm64/base.odex)
      75dd068218 void ero.onCreate() (/data/app/~~9YPINW14y2izqCbN0YZR6A==/com.google.android.apps.maps-WZHISLiw8lkQTFvs8_mhPw==/oat/arm64/base.odex)
        718d95e4 android.app.Instrumentation.callApplicationOnCreate (/system/framework/arm64/boot-framework.oat)
        719b1bc4 android.app.ActivityThread.handleBindApplication (/system/framework/arm64/boot-framework.oat)
        719a6f54 android.app.ActivityThread$H.handleMessage (/system/framework/arm64/boot-framework.oat)
        71bc2b5c android.os.Handler.dispatchMessage (/system/framework/arm64/boot-framework.oat)
        71bc598c android.os.Looper.loopOnce (/system/framework/arm64/boot-framework.oat)
        71bc54e4 android.os.Looper.loop (/system/framework/arm64/boot-framework.oat)
        719b98ec android.app.ActivityThread.main (/system/framework/arm64/boot-framework.oat)
      764ef0afe8 art_quick_invoke_static_stub (/apex/com.android.art/lib64/libart.so)
      764ef9b698 _jobject* art::InvokeMethod<(art::PointerSize)8>(art::ScopedObjectAccessAlreadyRunnable const&, _jobject*, _jobject*, _jobject*, unsigned long) (/apex/com.android.art/lib64/libart.so)
      764ef9b28c art::Method_invoke(_JNIEnv*, _jobject*, _jobject*, _jobjectArray*) (/apex/com.android.art/lib64/libart.so)
        702dcf74 art_jni_trampoline (/apex/com.android.art/javalib/arm64/boot.oat)
        71ecd41c com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run (/system/framework/arm64/boot-framework.oat)
        71ed5718 com.android.internal.os.ZygoteInit.main (/system/framework/arm64/boot-framework.oat)
      764ef0afe8 art_quick_invoke_static_stub (/apex/com.android.art/lib64/libart.so)
      764eff9b28 art::JValue art::InvokeWithVarArgs<_jmethodID*>(art::ScopedObjectAccessAlreadyRunnable const&, _jobject*, _jmethodID*, std::__va_list) (/apex/com.android.art/lib64/libart.so)
      764eff92a0 art::JNI<true>::CallStaticVoidMethodV(_JNIEnv*, _jclass*, _jmethodID*, std::__va_list) (/apex/com.android.art/lib64/libart.so)
      78f3cb2ac4 _JNIEnv::CallStaticVoidMethod(_jclass*, _jmethodID*, ...) (/system/lib64/libandroid_runtime.so)
      78f3cbdf48 android::AndroidRuntime::start(char const*, android::Vector<android::String8> const&, bool) (/system/lib64/libandroid_runtime.so)
      648b19258c main (/system/bin/app_process64)
      78fbeeb8ac __libc_init (/apex/com.android.runtime/lib64/bionic/libc.so)

I think the art::JValue is a return value and art::InvokeWithVarArgs<_jmethodID*>(...) is the function.