Bug 392085

Summary: Heaptrack gets all available memory and gets killed
Product: [Applications] Heaptrack Reporter: Anthony Fieroni <bvbfan>
Component: generalAssignee: Milian Wolff <mail>
Status: RESOLVED FIXED    
Severity: normal    
Priority: NOR    
Version First Reported In: unspecified   
Target Milestone: ---   
Platform: Other   
OS: Linux   
Latest Commit: Version Fixed In:
Sentry Crash Report:

Description Anthony Fieroni 2018-03-20 05:31:31 UTC
1. Latest git
2. compile it
3. Navigate to bin folder in compilation directory
4. Run ./heatrack -d plasmashell
5. Click ctrl + c
6. Try to open it ./heaptrack --analyze heaptrack.plasmashell.<pid>
7. Heaptrack gets all RAM and dies
Comment 1 Milian Wolff 2018-03-20 14:24:41 UTC
please attach the file your get.

I tested your steps - it consumes  ~1.5GB for me, but it doesn't die.
Comment 2 Anthony Fieroni 2018-03-20 14:56:52 UTC
So you can wait 1~2 min or i can attach my file.
Comment 3 Milian Wolff 2018-03-20 14:58:12 UTC
please attach the file, and with "wait 1-2min" you mean while tracking plasmashell with heaptrack?
Comment 4 Anthony Fieroni 2018-04-19 18:46:27 UTC
Update to master - still it's killed

https://drive.google.com/open?id=1TXAgA-PGs_KBVNuenIqQcohcwfX032mK
Comment 5 Milian Wolff 2018-04-19 21:47:12 UTC
Reproduced with the latest file you attached. Inspecting the backtraces with `heaptrack_print` shows they are completely fubared. Just to double check, can you tell me the output of `git describe`? And you are sure you installed after compiling, to ensure it's not picking up some older heaptrack lib?

Oooh and now I see this:

reading file "heaptrack.plasmashell.27041.gz" - please wait, this might take some time...
Debuggee command was: /bin/bash -c exec /usr/bin/plasmashell 
Debuggee command was: /usr/bin/plasmashell

Seems like you somehow managed to run heaptrack on bash *and* plasma as its child - that shouldn't be possible... We don't support child process tracking, but somehow your heaptrack does it nevertheless. This would explain why the resulting data file is corrupt! It gets written to by multiple processes then probably... Ouch!
Comment 6 Milian Wolff 2018-04-19 21:50:27 UTC
What distribution and version are you using? How did you invoke heaptrack exactly? I cannot reproduce at all what you are seeing...
Comment 7 Anthony Fieroni 2018-04-20 06:43:19 UTC
Slow down, can you open the file?
I'm starting it in bin folder (as describe in first comment)
./heaptrack -d plasmashell
Distribution is KaOS
Comment 8 Anthony Fieroni 2018-04-20 06:48:32 UTC
Please explain what you see and why it shouldn't be possible?
Comment 9 Milian Wolff 2018-04-22 07:48:16 UTC
Git commit e253b08794c62a14c6a521c6f08a5721e7dffd1c by Milian Wolff.
Committed on 22/04/2018 at 07:38.
Pushed by mwolff into branch 'master'.

Mark files with duplicated debuggee entries as corrupt

Since we do not (yet) support tracking child processes, a data
file with two or more debuggee entries (lines starting with 'X')
has to be corrupt. I have no clue yet how one can generate those,
but for sure the data will be completely bogus and can trigger
all sorts of issues. Most notably, the backtraces will be randomly
broken and potentially even recursive then...

M  +6    -0    src/analyze/accumulatedtracedata.cpp

https://commits.kde.org/heaptrack/e253b08794c62a14c6a521c6f08a5721e7dffd1c
Comment 10 Milian Wolff 2018-04-22 07:56:00 UTC
I cannot open it with the GUI, it also goes through all of my memory and then dies. But I can open it with `heaptrack_print`, which doesn't implement the full algorithm to merge backtraces. Thus it doesn't require that much memory, and can display us (some of) the results. This shows us (before the commit I just pushed) these results:

```
$ heaptrack_print heaptrack.plasmashell.27041.gz |& less
reading file "heaptrack.plasmashell.27041.gz" - please wait, this might take some time...
Debuggee command was: /bin/bash -c exec /usr/bin/plasmashell 
Debuggee command was: /usr/bin/plasmashel
finished reading file, now analyzing data:

MOST CALLS TO ALLOCATION FUNCTIONS
5535694 calls to allocation functions with 7.99MB peak consumption from
0x7ffff29b71e2
  in /usr/lib/libQt5Core.so.5
1046100 calls with 0B peak consumption from:
    0x7fffd0ff6f3c
      in ??
    0x7fffd10be97f
      in /usr/lib/dri/i965_dri.so
    0x7fffd0ff7008
      in /usr/lib/dri/i965_dri.so
    0x7fffd1232768
      in /usr/lib/dri/i965_dri.so
    0x7fffd10893df
      in /usr/lib/dri/i965_dri.so
    0x7fffd0ff7284
      in ??
    0x7fffd0ff7008
      in /usr/lib/dri/i965_dri.so
    QFileInfo::QFileInfo(QString const&)
      in /usr/lib/libQt5Core.so.5
    QArrayData::allocate(unsigned long, unsigned long, unsigned long, QFlags<>)
      in /usr/lib/libQt5Core.so.5
    0x7ffff26440e7
      in /usr/lib/libstdc++.so.6
    0x7ffff2a44869
      in /usr/lib/libQt5Core.so.5
    QByteArray::reallocData(unsigned int, QFlags<>)
      in /usr/lib/libQt5Core.so.5
    0x7fffd0ff6f3c
      in ??
    QArrayData::reallocateUnaligned(QArrayData*, unsigned long, unsigned long, QFlags<>)
      in /usr/lib/libQt5Core.so.5
    0x7fff45dc62f4
      in /usr/lib/qt5/qml/org/kde/plasma/core/libcorebindingsplugin.so
    0x7ffff4ff40eb
      in /usr/lib/libQt5Qml.so.5
    0x7ffff60f0e7c
      in /usr/lib/libKF5Plasma.so.5
    Plasma::Theme::findInRectsCache(QString const&, QString const&, QRectF&) const
      in /usr/lib/libKF5Plasma.so.5
    QV4::Runtime::method_callActivationProperty(QV4::ExecutionEngine*, int, QV4::CallData*)
      in /usr/lib/libQt5Qml.so.5
    0x7fff400c27bb
      in ??
    0x7ffff2c1237a
      in /usr/lib/libQt5Core.so.5
    0x7fffe2a5828d
      in /usr/lib/qt5/plugins/platforms/../../../libfontconfig.so.1
    QTextLine::setLineWidth(double)
      in /usr/lib/libQt5Gui.so.5
    0x7ffff51434e5
      in /usr/lib/libQt5Qml.so.5
    0x7fffd19992a7
      in /usr/lib/qt5/qml/QtQuick/Layouts/libqquicklayoutsplugin.so
    0x7ffff2a44869
      in /usr/lib/libQt5Core.so.5
    QObjectPrivate::connectImpl(QObject const*, int, QObject const*, void**, QtPrivate::QSlotObjectBase*, Qt::ConnectionType, int const*, QMetaObject const*)
      in /usr/lib/libQt5Core.so.5
    QArrayData::allocate(unsigned long, unsigned long, unsigned long, QFlags<>)
      in /usr/lib/libQt5Core.so.5
    QQmlData::deferData(int, QV4::CompiledData::CompilationUnit*, QQmlContextData*)
      in /usr/lib/libQt5Qml.so.5
    QObjectPrivate::setParent_helper(QObject*)
      in /usr/lib/libQt5Core.so.5
    0x7ffff2b574bb
      in /usr/lib/libQt5Core.so.5
    0x7ffff26440e7
      in /usr/lib/libstdc++.so.6
    QByteArray::QByteArray(int, Qt::Initialization)
      in /usr/lib/libQt5Core.so.5
    QQuickItem::geometryChanged(QRectF const&, QRectF const&)
      in /usr/lib/libQt5Quick.so.5
    QString::reallocData(unsigned int, bool)
      in /usr/lib/libQt5Core.so.5
    0x7ffff5bc9bb9
      in /usr/lib/libQt5Quick.so.5
    QCoreApplication::notifyInternal2(QObject*, QEvent*)
      in /usr/lib/libQt5Core.so.5
    0x7ffff501f3a4
      in /usr/lib/libQt5Qml.so.5
    0x7ffff2c266fb
      in /usr/lib/libQt5Core.so.5
    QArrayData::allocate(unsigned long, unsigned long, unsigned long, QFlags<>)
      in /usr/lib/libQt5Core.so.5
    0x7ffff501f3a4
      in /usr/lib/libQt5Qml.so.5
    QV4::QObjectWrapper::setProperty(QV4::ExecutionEngine*, QObject*, QQmlPropertyData*, QV4::Value const&)
      in /usr/lib/libQt5Qml.so.5
    QMetaObject::activate(QObject*, int, int, void**)
      in /usr/lib/libQt5Core.so.5
    QV4::Script::parse()
      in /usr/lib/libQt5Qml.so.5
    QV4::ExecutionContext::simpleCall(QV4::Scope&, QV4::CallData*, QV4::Function*)
      in /usr/lib/libQt5Qml.so.5
    0x7fff400be7aa
      in ??
    QV4::QQmlValueTypeWrapper::toVariant() const
      in /usr/lib/libQt5Qml.so.5
    QString::number(long long, int)
      in /usr/lib/libQt5Core.so.5
    QQuickMouseArea::qt_metacall(QMetaObject::Call, int, void**)
      in /usr/lib/libQt5Quick.so.5
    0x7ffff5088894
      in /usr/lib/libQt5Qml.so.5
    QV4::ExecutionContext::simpleCall(QV4::Scope&, QV4::CallData*, QV4::Function*)
      in /usr/lib/libQt5Qml.so.5
    QV4::Runtime::method_callActivationProperty(QV4::ExecutionEngine*, int, QV4::CallData*)
      in /usr/lib/libQt5Qml.so.5
    0x7ffff508e9ce
      in /usr/lib/libQt5Qml.so.5
    0x7fff400ba1bc
      in ??
    0x7ffff501f3a4
      in /usr/lib/libQt5Qml.so.5
    0x7fff400ba1bc
      in ??
    0x7ffff501f3a4
      in /usr/lib/libQt5Qml.so.5
    QQuickItem::setSize(QSizeF const&)
      in /usr/lib/libQt5Quick.so.5
    0x7fff40081cb5
      in ??
    QV4::ExecutionContext::simpleCall(QV4::Scope&, QV4::CallData*, QV4::Function*)
      in /usr/lib/libQt5Qml.so.5
    QV4::QObjectWrapper::getQmlProperty(QQmlContextData*, QV4::String*, QV4::QObjectWrapper::RevisionMode, bool*, bool) const
      in /usr/lib/libQt5Qml.so.5
    0x7ffff508d2b0
      in /usr/lib/libQt5Qml.so.5
    QV4::ExecutionContext::simpleCall(QV4::Scope&, QV4::CallData*, QV4::Function*)
      in /usr/lib/libQt5Qml.so.5
    QV4::Runtime::method_callActivationProperty(QV4::ExecutionEngine*, int, QV4::CallData*)
      in /usr/lib/libQt5Qml.so.5
    QV4::ExecutionContext::simpleCall(QV4::Scope&, QV4::CallData*, QV4::Function*)
      in /usr/lib/libQt5Qml.so.5
    0x7fff400c221b
      in ??
    QQuickImplicitSizeItem::qt_metacall(QMetaObject::Call, int, void**)
      in /usr/lib/libQt5Quick.so.5
    QQuickItemPrivate::itemChange(QQuickItem::ItemChange, QQuickItem::ItemChangeData const&)
      in /usr/lib/libQt5Quick.so.5
    0x7ffff60f06b8
      in /usr/lib/libKF5Plasma.so.5
    QV4::IR::Optimizer::lifeTimeIntervals() const
      in /usr/lib/libQt5Qml.so.5
    QString::QString(int, Qt::Initialization)
      in /usr/lib/libQt5Core.so.5
    0x7fffd0137cda
      in ??
    QString::number(int, int)
      in /usr/lib/libQt5Core.so.5
    QString::QString(int, Qt::Initialization)
      in /usr/lib/libQt5Core.so.5
    QString::resize(int)
      in /usr/lib/libQt5Core.so.5
...
```

Note: The above is supposed to be _one_ backtrace. But it's clearly completely broken. Just look at the end of the snippet I showed (it goes on and on):

```
    QString::number(int, int)
      in /usr/lib/libQt5Core.so.5
    QString::QString(int, Qt::Initialization)
      in /usr/lib/libQt5Core.so.5
    QString::resize(int)
      in /usr/lib/libQt5Core.so.5
```

`QString::resize` does _not_ go into `QString::number` eventually, ever. Something completely corrupted the data file. Now look at the beginning of the output:

```
Debuggee command was: /bin/bash -c exec /usr/bin/plasmashell 
Debuggee command was: /usr/bin/plasmashell
```

This happens because your data file contains _two_ lines starting with 'X', which should not ever happen. Somehow, you managed to inject heaptrack into two processes (bash and plasmashell), and both wrote to the same output which then corrupted the file.

But again - I have no idea how that happens on your system... I'll try once more to reproduce it. Question: what do you get for `alias plasmashell` or `which plasmashell`?
Comment 11 Milian Wolff 2018-04-22 08:00:35 UTC
Aha! I can reproduce your problem when I try to run `heaptrack -d plasmashell`. It doesn't happen when I don't use the debug mode (i.e. remove the -d). I'll inspect and try to fix this now - thanks a lot for the report!
Comment 12 Milian Wolff 2018-04-22 08:15:33 UTC
Git commit a6839d6f36dfd24cdd99205b395d46d8ff7e0185 by Milian Wolff.
Committed on 22/04/2018 at 08:04.
Pushed by mwolff into branch 'master'.

Error out early during recording when receiving child process events

Heaptrack does not yet support recording child processes. But
apparently it can happen that we actually trace child processes when
we use `heaptrack -d`. This then leads to corrupted data files.
This patch catches this scenario early and errors out then.

M  +4    -0    src/interpret/heaptrack_interpret.cpp

https://commits.kde.org/heaptrack/a6839d6f36dfd24cdd99205b395d46d8ff7e0185
Comment 13 Milian Wolff 2018-04-22 08:15:33 UTC
Git commit dfb6123a6b1c5a925f4c346e5737d7129a20c683 by Milian Wolff.
Committed on 22/04/2018 at 08:13.
Pushed by mwolff into branch 'master'.

Do not use shell to launch new programs in debug mode

When we want to debug heaptrack we use GDB to launch the new
process. By default, that actually first starts a shell and then
eventually the debuggee. But both processes would get heaptrack
injected and will then write to the same heaptrack_interpret
process, thereby corrupting the data file.

By using `set startup-with-shell off` in GDB, we can eliminate the
shell and prevent this issue from occurring.

M  +1    -0    src/track/heaptrack.sh.cmake

https://commits.kde.org/heaptrack/dfb6123a6b1c5a925f4c346e5737d7129a20c683
Comment 14 Anthony Fieroni 2018-04-23 06:39:21 UTC
I *really* should make new trace but even with this i can speculate over plasma' theme cache.
Comment 15 Anthony Fieroni 2018-04-23 06:47:14 UTC
Furthermore i mount my ~/.cache folder as tmpfs which can lead in much ram consumption, but it's intersting to me.