search

sardana-org / sardana

Moved to GitLab: https://gitlab.com/sardana-org/sardana
39 stars 52 forks source link

100% CPU usage from sequenceeditor (SF#485) #330

Closed sf-migrator-bot closed 7 years ago

sf-migrator-bot commented 8 years ago

Hi,

Our users complain about macrogui widgets that from time to fime CPU usage is 100% almost constant. Therefore they cannot use it any more.

Running cProfile it has turned out that one of this usage sources is sequencereditor, i.e. its emit of dataChanged, i.e.

 self.emit(Qt.SIGNAL("dataChanged(QModelIndex,QModelIndex)"), index, index.sibling(index.row(), self.columnCount(index)))

Also perf shows

 Samples: 83K of event 'cycles', Event count (approx.): 38399428438                                                                              
  55.78%  libQtGui.so.4.8.6                [.] QHeaderView::visualIndex(int) const
  21.27%  libQtGui.so.4.8.6                [.] QHeaderView::resizeMode(int) const
  14.45%  libQtGui.so.4.8.6                [.] QHeaderView::dataChanged(QModelIndex const&, QModelIndex const&)
   0.31%  libc-2.19.so                     [.] vfprintf
   0.18%  [kernel]                         [k] __gen6_gt_force_wake_get

that it means that there are problems with resizing headers to its contents.

Actually, I don't know what is the reason of the behavior , i.e. Sardana, Taurus, PyQt4 or Gnome3 but to fix it I propose replacing the emit code to its equivalent, namely:

diff --git a/src/sardana/taurus/qt/qtgui/extra_macroexecutor/sequenceeditor/model.py b/src/sardana/taurus/qt/qtgui/extra_macroexecutor/sequenceeditor/model.py
index 00ed7e5..b9b681d 100644
--- a/src/sardana/taurus/qt/qtgui/extra_macroexecutor/sequenceeditor/model.py
+++ b/src/sardana/taurus/qt/qtgui/extra_macroexecutor/sequenceeditor/model.py
@@ -181,7 +181,10 @@ class MacroSequenceTreeModel(Qt.QAbstractItemModel):
                     index = index.parent()
                     node = self.nodeFromIndex(index)
                     if isinstance(node, macro.MacroNode):
-                        self.emit(Qt.SIGNAL("dataChanged(QModelIndex,QModelIndex)"), index, index.sibling(index.row(), self.columnCount(index)))
+                        for i in range(self.columnCount(index) + 1):
+                            iindex = index.sibling(index.row(), i)
+                            self.emit(Qt.SIGNAL("dataChanged(QModelIndex, QModelIndex)"),
+                                      iindex, iindex)
                         break
         elif index.column() == 2:
             progress = Qt.from_qvariant(value, float)

Bests, Jan

Reported by: jkotan ( http://sf.net/u/jkotan )

Original Ticket: sardana/tickets/485

sf-migrator-bot commented 8 years ago

Hi,

other option to fix the bug is

diff --git a/src/sardana/taurus/qt/qtgui/extra_macroexecutor/sequenceeditor/model.py b/src/sardana/taurus/qt/qtgui/extra_macroexecutor/sequenceeditor/model.py
index 00ed7e5..dab27a7 100644
--- a/src/sardana/taurus/qt/qtgui/extra_macroexecutor/sequenceeditor/model.py
+++ b/src/sardana/taurus/qt/qtgui/extra_macroexecutor/sequenceeditor/model.py
@@ -181,7 +181,7 @@ class MacroSequenceTreeModel(Qt.QAbstractItemModel):
                     index = index.parent()
                     node = self.nodeFromIndex(index)
                     if isinstance(node, macro.MacroNode):
-                        self.emit(Qt.SIGNAL("dataChanged(QModelIndex,QModelIndex)"), index, index.sibling(index.row(), self.columnCount(index)))
+                        self.emit(Qt.SIGNAL("dataChanged(QModelIndex &,QModelIndex &)"), index, index.sibling(index.row(), self.columnCount(index)))
                         break
         elif index.column() == 2:
             progress = Qt.from_qvariant(value, float)

i. e. it seems that in a new version of Qt & are required at least when we have a range of indexes.

P.S. similar issue we have in taurus.

Bests, Jan

Original comment by: jkotan (http://sf.net/u/jkotan)

sf-migrator-bot commented 8 years ago

Unfortunately, the second fix is wrong. It does not sent the signal. One can inprove it by adding const infront of QModelIndex but then we go back to version with 100% CPU.

The first fix (with the loop) still works.

Original comment by: jkotan (http://sf.net/u/jkotan)

sf-migrator-bot commented 8 years ago

Hi,

I've just noticed that columns are wrongly counted (we start from 0) so it should be 

diff --git a/src/sardana/taurus/qt/qtgui/extra_macroexecutor/sequenceeditor/model.py b/src/sardana/taurus/qt/qtgui/extra_macroexecutor/sequenceeditor/model.py
index 00ed7e5..0beddcb 100644
--- a/src/sardana/taurus/qt/qtgui/extra_macroexecutor/sequenceeditor/model.py
+++ b/src/sardana/taurus/qt/qtgui/extra_macroexecutor/sequenceeditor/model.py
@@ -181,7 +181,7 @@ class MacroSequenceTreeModel(Qt.QAbstractItemModel):
                     index = index.parent()
                     node = self.nodeFromIndex(index)
                     if isinstance(node, macro.MacroNode):
-                        self.emit(Qt.SIGNAL("dataChanged(QModelIndex,QModelIndex)"), index, index.sibling(index.row(), self.columnCount(index)))
+                        self.emit(Qt.SIGNAL("dataChanged(QModelIndex,QModelIndex)"), index, index.sibling(index.row(), self.columnCount(index)-1))
                         break
         elif index.column() == 2:
             progress = Qt.from_qvariant(value, float)

what fixes the bug.

Bests , Jan

Original comment by: jkotan (http://sf.net/u/jkotan)

sf-migrator-bot commented 8 years ago

Original comment by: jkotan (http://sf.net/u/jkotan)

sf-migrator-bot commented 8 years ago

Hi Jan,

Thanks for the report. I have tried it on my PC but I could not reproduce 100% of CPU. I observe approx. 7 % (what is quite a lot anyway..). I use PyQt 4.8.5 and KDE 4.11.5. Could you share with us your versions? Which options of perf and cProfile have you used to obtain the above results? And the last question is, which patch is the correct one: the first one (with the loop) or the last one with self.columnCount(index)-1.

Thanks!

Original comment by: reszelaz (http://sf.net/u/zreszela)

sf-migrator-bot commented 8 years ago

Hi Zibi,

The last version with - 1 is correct.

The first version with loop is a workaround for the bug but it has a similar bug as the original code, i. e. it calls also dataChanged() on non-existing index (the last one in the loop) which is defined by unpredictable values. However, since this call is only on one index (not range of indexes as in the original code) it does not cause that qt is trying to figure out what are the indexes between the first one and the 'non-existing one'. In the original code such operation takes time because qt can find a lot of indexes in between (depending on 'random' values from the memory). The CPU usage may not only depends on version of python-qt but also with which flags the code was compiled, i.e. for debian the qt code may be compiled with different optimisation flags. The bug is similar to the situation in C++ where you define some array and read the values from the array with exceeded indexes (with array element interpretation). Since PyQt is not enough python you do not get exception in this situation.

I've made test on wheezy, jessie and stretch with newly updated packages. For stretch it appeared when I upgraded some packages (I think it was python-qt4 but source version was the same).

Now I sit at jessie with: python-qt4 4.11.2+dfsg-1
libqtcore4:amd64 4:4.8.6+git64-g5dc8b2b+dfsg-3+deb8u1 .... gnome-shell 3.14.4-1~deb8u1 (but on XFCE it also fails) ....

I use perf top but it is enough to run top.

The cProfile I run by 

python -m cProfile -o seq_test.profile seq_test.py

and you can see result in GUI e.g. by

runsnake seq_test.profile

Optionally, you can run callgrind but then you have to enlage time scale and be patient. But then you can get an idea what is going on inside (python-)qt4.

In the bellow code seq_test.py you can set your MacroServer, Door and Motor. TimeScale does not change to much. Of course you can also do what QTimers and SeqTools do by clicking.

import sardana
from sardana.taurus.qt.qtgui.extra_macroexecutor\
                            .sequenceeditor.sequenceeditor import *

from PyQt4.QtCore import QTimer, QModelIndex, QVariant

MS = 'MacroServer/jessie/1'
DOOR = 'Door/jessie/1'
MOTOR = 'mot01'
TIMESCALE = 2

class SeqTools(object):
    def __init__(self, seq, motorname):
        self.tseq = seq
        self.motorname = motorname
        self.widget = seq.taurusSequencerWidget
        self.smpe = self.widget.standardMacroParametersEditor
        self.tree = self.smpe.tree

    def setmacro(self):
        print("*********** set MACRO ***********")
        index = self.widget.macroComboBox.findText('ascan')
        self.widget.macroComboBox.setCurrentIndex(index)
        self.widget.onMacroComboBoxChanged()

    def addmacro(self):
        print("*********** add MACRO ***********")
        self.widget.addMacroAction.trigger()

    def setmotor(self):
        print("*********** set MOTOR ***********")
        root0 = self.tree.model().index(0, 0, QModelIndex())
        mot0 = self.tree.model().index(0, 0, root0)
        mot1 = self.tree.model().index(0, 1, root0)
        self.tree.model().setData(mot1, self.motorname)
        print("MOT %s %s " % (
            self.tree.model().data(mot0, Qt.Qt.DisplayRole),
            self.tree.model().data(mot1, Qt.Qt.DisplayRole)
        ))

    def setstart(self):
        print("*********** set start ***********")
        root0 = self.tree.model().index(0, 0, QModelIndex())
        st0 = self.tree.model().index(1, 0, root0)
        st1 = self.tree.model().index(1, 1, root0)
        self.tree.model().setData(st1, "0.0")
        print("%s %s " % (
            self.tree.model().data(st0, Qt.Qt.DisplayRole),
            self.tree.model().data(st1, Qt.Qt.DisplayRole)
        ))

def main():
    from taurus.qt.qtgui.application import TaurusApplication
    import taurus

    app = TaurusApplication(sys.argv, app_version=sardana.Release.version)
    args = app.get_command_line_args()
    args = [MS, DOOR]
    print (args)

    app.setOrganizationName("DESY")
    app.setApplicationName("SEQTEST")
    sequencer = createSequencer(args)
    sequencer.show()

    st = SeqTools(sequencer, MOTOR)
    QTimer.singleShot(2000, st.setmacro)
    QTimer.singleShot(3000, st.addmacro)
    for i in range(10):
        QTimer.singleShot(4000 + (i * 100) * TIMESCALE, st.setmotor)
        QTimer.singleShot(4000 + (i * 150) * TIMESCALE, st.setstart)

    status = app.exec_()
    sys.exit(status)

if __name__ == "__main__":
    main()

Bests, Jan

Original comment by: jkotan (http://sf.net/u/jkotan)

sf-migrator-bot commented 8 years ago

Original comment by: reszelaz (http://sf.net/u/zreszela)

sf-migrator-bot commented 8 years ago

Hi Jan,

Thanks for the detailed explanation. You are totally right that the last index should be reduced by one. I have already pushed that into the develop branch.

Unfortunatelly we were not able to reproduce this issue, but after your deep analysis I would consider this issue as closed.

We have tried it on a virtual machine with Debian Jessie with:

And also on a real machine with Debian Stretch with:

Cheers, Zibi

Original comment by: reszelaz (http://sf.net/u/zreszela)