new lag issues Jan 2023

Including three types of lag in this issue. All of them were noticed while creating and then later reloading of a previous log with many callsigns (>50) which was used for testing of #391, which had only one entry per callsign on average. So, the lag is not due to a lot of entries.

[x] 1. lag on accept for first entry of a new team, after 'extTeamName List after sort' and before 'resize detected' or 'next available hotkey'. Note that resize happened after each new callsign's first entry since each new team tab just kept increasing the main window width (to be greater than the width of both screens - apparently there was/is no max width specified) ~~2. lag after first keypress until open of NED~~ (cannot reproduce)
[x] 3. lag during load: increasing lag with increasing callsign count. Note as above that each callsign only had one entry on average.

A good test would be to go back several versions and see if the same lag exists.

Loading into 3.4.0 shows some good leads. Basically there are a zillion tracebacks like so:

Uncaught exception
Traceback (most recent call last):
  File "radiolog.py", line 7414, in headerData
IndexError: list index out of range

In every case, the tracebacks are between 'extTeamNameList after sort' and 'next available hotkey', and again until 'newEntry called with these values'.

Starting from 'Loading' - for shorthand, the number of tracebacks is shown below as '#x tb' - 10x tb means the 4-line traceback happened 10 times in a row:

093006:Loading: C:/Users/caver/RadioLog/New_Incident_2023_01_21_155247-full.csv
093006:loaded incident name: 'New Incident'
093006:normalized loaded incident name: 'New_Incident'
093006:  t1 - done reading file
093006:newEntry called with these values:
093006:['1541', '', '', 'Radio Log Begins: Sat Jan 21, 2023', '', '', 1674344474.091357, '', '', '', '']
093006:newEntry called with these values:
093006:['1541', 'FROM', 'Team 1', 'STARTING ASSIGNMENT', '', 'Working', 1674344483.7448304, '', '', '', '??']
093006:new team: newTeamName=Team 1 extTeamName=z_Team00001 niceTeamName=Team 1 shortNiceTeamName=1
093006:extTeamNameList before sort:['dummy', 'z_Team00001']
093006:grouped tabs:{'Numbers': ['z_Team00001'], 'other': ['dummy']}
093006:extTeamNameList after sort:['spacerLeft', 'z_Team00001', 'spacer1']
   5x tb
093006:next available hotkey:1
   5x tb
093006:newEntry called with these values:
093006:['1541', 'FROM', 'Team 2', 'STARTING ASSIGNMENT', '', 'Working', 1674344486.8552837, '', '', '', '??']
093006:new team: newTeamName=Team 2 extTeamName=z_Team00002 niceTeamName=Team 2 shortNiceTeamName=2
093007:extTeamNameList before sort:['spacerLeft', 'z_Team00001', 'spacer1', 'z_Team00002']
093007:grouped tabs:{'Numbers': ['z_Team00001', 'z_Team00002'], 'other': []}
093007:extTeamNameList after sort:['spacerLeft', 'z_Team00001', 'z_Team00002', 'spacer1']
  7x tb
093007:next available hotkey:2
  6x tb
093007:newEntry called with these values:
093007:['1544', '', '', 'Radio Log Begins: Sat Jan 21, 2023', '', '', 1674344647.137179, '', '', '', '']
093007:newEntry called with these values:
093007:['1552', '', '', 'Radio Log Begins: Sat Jan 21, 2023', '', '', 1674345161.7984593, '', '', '', '']
093007:newEntry called with these values:
093007:['1702', 'FROM', 'Team 12345', 'STARTING ASSIGNMENT', '', 'Working', 1674349374.4368582, '', '', '', '??']
093007:new team: newTeamName=Team 12345 extTeamName=z_Team12345 niceTeamName=Team 12345 shortNiceTeamName=12345
093007:extTeamNameList before sort:['spacerLeft', 'z_Team00001', 'z_Team00002', 'spacer1', 'z_Team12345']
093007:grouped tabs:{'Numbers': ['z_Team00001', 'z_Team00002', 'z_Team12345'], 'other': []}
093007:extTeamNameList after sort:['spacerLeft', 'z_Team00001', 'z_Team00002', 'z_Team12345', 'spacer1']
  9x tb
093007:next available hotkey:3
  7x tb
093007:newEntry called with these values:
093007:['1703', 'FROM', 'Team 12346', 'STARTING ASSIGNMENT', '', 'Working', 1674349380.2940485, '', '', '', '??']
093007:new team: newTeamName=Team 12346 extTeamName=z_Team12346 niceTeamName=Team 12346 shortNiceTeamName=12346
093007:extTeamNameList before sort:['spacerLeft', 'z_Team00001', 'z_Team00002', 'z_Team12345', 'spacer1', 'z_Team12346']
093007:grouped tabs:{'Numbers': ['z_Team00001', 'z_Team00002', 'z_Team12345', 'z_Team12346'], 'other': []}
093007:extTeamNameList after sort:['spacerLeft', 'z_Team00001', 'z_Team00002', 'z_Team12345', 'z_Team12346', 'spacer1']
  11x tb
093007:next available hotkey:4
  8x cb

And so on. The counts after the final 'extTeamNameList after sort' line are 113 and 60, immediately after which:

093100:  t2
093100:  t3
  1x tb
093102:  t4
  1x tb
093102:  t5
093102:  t6
093102:  t7
  633x tb
093104:  t8
093104:  t9
093104:  t10
093104:  t11
093104:  t12
093104:Renamed session directory to "C:\Users\caver\RadioLog\New_Incident_2023_01_22_093104"
093104:  t13
093104:  t14
  1x tb

Then a few more tracebacks scattered after 'arraydata:' prints and 'resize detected' lines, either in groups of one or two tracebacks.

The pattern seems to be that the number of tracebacks in the first group, after extTeamNameList, increases by two with each new entry, and the number of tracebacks in the second group increases by one with each new entry. Since most of these calls involve new teams, this pattern isn't a good test of what happens per entry without new teams.

Still - this should be fairly easy to track down. Guessing it has to do with the operator initials entry introduced in 3.5.0. If that's the case, this might be a backwards-compatibility issue (3.4.0 doesn't gracefully read a .csv created with 3.5.0). At least the tracebacks aren't fatal. But the lag still exists in 3.5.0 so these tracebacks might or might not be directly relevant - but, they do indicate how many times a certain piece of code is being called, which can hopefully be optimized.

Couldn't tell exactly which version of the code this came from, i.e. which version had line 7414 inside the headerData function, but, pretty safe to say it's this code. Sure enough, this is due to operatorInitials not being defined in the header_labels list; it has been added in 3.5.0 so the same tracebacks won't happen in 3.5.0 and up, but, it shows how many times headerData is being called. So the key is to focus on reducing that number. Maybe just freezing the display during load would do the trick? I'm sure that's been tried and abandoned years ago, but, looks like time to try again.

class MyTableModel(QAbstractTableModel):
    header_labels=['TIME','T/F','TEAM','MESSAGE','RADIO LOC.','STATUS','sec','fleet','dev','origLoc']
    def __init__(self, datain, parent=None, *args):
        QAbstractTableModel.__init__(self, parent, *args)
        self.arraydata=datain

    def headerData(self,section,orientation,role=Qt.DisplayRole):
#       print("headerData:",section,",",orientation,",",role)
        if role==Qt.DisplayRole and orientation==Qt.Horizontal:
            return self.header_labels[section]
        return QAbstractTableModel.headerData(self,section,orientation,role)

surrounding the loop which calls self.newEntry in self.setUpdatesEnabled(False) then self.setUpdatesEnabled(True) had no change in load time. Also there was no visual difference - the window expanded incrementally to fit the 'overflow' callsigns in each case. Might need to look at 'deeper' pause options - disconnecting the model at the start of the loop and reconnecting it when done, or something to that effect?

cProfiler gives some interesting results. The list is LONG but this is the set including everything with cumulative time of a tenth of a second or more. The actions performed:

open radiolog
cancel on all the opening dialogs (continuedIncident, options, login)
F4 to open a file
click 'Use Browser'
navigate to the file in question and click OK to start the load process
exit radiolog after load is complete

Sun Jan 22 19:43:13 2023    profile.txt

         4120517 function calls (4111495 primitive calls) in 26.527 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    360/1    0.001    0.000   37.806   37.806 {built-in method builtins.exec}
        1    0.000    0.000   37.806   37.806 radiolog.py:1(<module>)
        1    0.018    0.018   37.107   37.107 radiolog.py:8336(main)
      6/5   12.611    2.102   28.048    5.610 {built-in method exec_}
        1    0.000    0.000   22.211   22.211 radiolog.py:3414(keyPressEvent)
      2/1    0.003    0.002   22.211   22.211 radiolog.py:3733(load)
        1    0.007    0.007   20.383   20.383 radiolog.py:7396(useBrowserClicked)
       37    0.001    0.000   12.061    0.326 radiolog.py:4155(newEntry)
       37    0.001    0.000   12.022    0.325 radiolog.py:4213(newEntryProcessTeam)
       33    0.002    0.000   12.014    0.364 radiolog.py:4388(newTeam)
       33    0.004    0.000   11.729    0.355 radiolog.py:4352(rebuildTabs)
      627    0.100    0.000   11.454    0.018 radiolog.py:4521(addTab)
      629    3.000    0.005    3.216    0.005 {built-in method insertTab}
        1    0.002    0.002    2.977    2.977 radiolog.py:654(__init__)
        1    0.000    0.000    2.277    2.277 radiolog.py:1290(checkForContinuedIncident)
        1    0.000    0.000    2.204    2.204 radiolog.py:3206(startupOptions)
        1    0.012    0.012    2.032    2.032 radiolog.py:3486(closeEvent)
      630    0.938    0.001    1.799    0.003 {built-in method setModel}
    41579    0.212    0.000    1.749    0.000 radiolog.py:8247(filterAcceptsRow)
      627    1.161    0.002    1.432    0.002 radiolog.py:8106(__init__)
      665    1.134    0.002    1.362    0.002 {built-in method resizeRowsToContents}
   392212    0.663    0.000    1.120    0.000 radiolog.py:8302(eventFilter)
        2    0.068    0.034    1.068    0.534 {method 'emit' of 'PyQt5.QtCore.pyqtBoundSignal' objects}
    41686    0.344    0.000    0.838    0.000 radiolog.py:435(getExtTeamName)
   407/21    0.004    0.000    0.693    0.033 <frozen importlib._bootstrap>:1022(_find_and_load)
   405/21    0.002    0.000    0.692    0.033 <frozen importlib._bootstrap>:987(_find_and_load_unlocked)
   387/24    0.002    0.000    0.678    0.028 <frozen importlib._bootstrap>:664(_load_unlocked)
   345/21    0.001    0.000    0.668    0.032 <frozen importlib._bootstrap_external>:877(exec_module)
   469/27    0.000    0.000    0.668    0.025 <frozen importlib._bootstrap>:233(_call_with_frames_removed)
        7    0.562    0.080    0.608    0.087 {built-in method show}
     2871    0.524    0.000    0.576    0.000 {built-in method setStyleSheet}
      627    0.542    0.001    0.566    0.001 {built-in method setTabButton}
        2    0.000    0.000    0.515    0.257 radiolog.py:3223(fontsChanged)
        1    0.000    0.000    0.481    0.481 radiolog.py:5365(__init__)
      222    0.468    0.002    0.470    0.002 {built-in method setFont}
        1    0.002    0.002    0.468    0.468 C:\Users\caver\Documents\GitHub\radiolog\ui\options_ui.py:15(setupUi)
    41579    0.154    0.000    0.378    0.000 {built-in method data}
    82364    0.262    0.000    0.306    0.000 radiolog.py:8028(data)
    60/26    0.000    0.000    0.281    0.011 {built-in method builtins.__import__}
   392212    0.278    0.000    0.278    0.000 {built-in method type}
      592    0.251    0.000    0.270    0.000 {built-in method removeTab}
       38    0.243    0.006    0.268    0.007 {processEvents}
        1    0.000    0.000    0.263    0.263 C:\Program Files (x86)\Python310-32\lib\site-packages\requests\__init__.py:1(<module>)
    84871    0.070    0.000    0.255    0.000 C:\Program Files (x86)\Python310-32\lib\re.py:288(_compile)
   147/97    0.000    0.000    0.245    0.003 <frozen importlib._bootstrap>:1053(_handle_fromlist)
        2    0.000    0.000    0.221    0.111 radiolog.py:3277(redrawTables)
       33    0.027    0.001    0.215    0.007 radiolog.py:5181(rebuildTeamHotkeys)
      345    0.004    0.000    0.202    0.001 <frozen importlib._bootstrap_external>:950(get_code)
       18    0.001    0.000    0.193    0.011 radiolog.py:1668(fsCheck)
   392212    0.179    0.000    0.179    0.000 {function customEventFilter.eventFilter at 0x05691730}
  401/363    0.003    0.000    0.171    0.000 <frozen importlib._bootstrap>:921(_find_spec)
       18    0.000    0.000    0.164    0.009 C:\Users\caver\AppData\Roaming\Python\Python310-32\site-packages\serial\tools\list_ports_windows.py:419(comports)
       54    0.161    0.003    0.163    0.003 C:\Users\caver\AppData\Roaming\Python\Python310-32\site-packages\serial\tools\list_ports_windows.py:238(iterate_comports)
    41692    0.038    0.000    0.160    0.000 C:\Program Files (x86)\Python310-32\lib\re.py:202(sub)
        1    0.000    0.000    0.149    0.149 C:\Users\caver\AppData\Roaming\Python\Python310-32\site-packages\reportlab\platypus\__init__.py:1(<module>)
      135    0.001    0.000    0.148    0.001 C:\Program Files (x86)\Python310-32\lib\sre_compile.py:759(compile)
      134    0.000    0.000    0.147    0.001 C:\Program Files (x86)\Python310-32\lib\re.py:249(compile)
        1    0.000    0.000    0.131    0.131 C:\Program Files (x86)\Python310-32\lib\site-packages\urllib3\__init__.py:1(<module>)
      313    0.002    0.000    0.131    0.000 radiolog.py:560(rprint)
      313    0.001    0.000    0.125    0.000 C:\Program Files (x86)\Python310-32\lib\logging\__init__.py:1458(info)
      345    0.002    0.000    0.124    0.000 <frozen importlib._bootstrap_external>:1070(get_data)
      313    0.001    0.000    0.123    0.000 C:\Program Files (x86)\Python310-32\lib\logging\__init__.py:1591(_log)
      383    0.001    0.000    0.120    0.000 <frozen importlib._bootstrap_external>:1422(find_spec)
      383    0.002    0.000    0.120    0.000 <frozen importlib._bootstrap_external>:1390(_get_spec)
      782    0.009    0.000    0.114    0.000 <frozen importlib._bootstrap_external>:1527(find_spec)
      706    0.104    0.000    0.114    0.000 {built-in method addWidget}
46661/46593    0.050    0.000    0.113    0.000 {method 'join' of 'str' objects}
    42346    0.035    0.000    0.113    0.000 C:\Program Files (x86)\Python310-32\lib\re.py:197(search)
    78424    0.065    0.000    0.111    0.000 radiolog.py:8013(headerData)
   147867    0.078    0.000    0.104    0.000 radiolog.py:8022(rowCount)
     2268    0.103    0.000    0.103    0.000 {built-in method nt.stat}
      313    0.001    0.000    0.102    0.000 C:\Program Files (x86)\Python310-32\lib\logging\__init__.py:1617(handle)
      313    0.002    0.000    0.101    0.000 C:\Program Files (x86)\Python310-32\lib\logging\__init__.py:1671(callHandlers)

Some questions that arise from the profile:

why is addTab (and insertTab) called 627 times? This causes a similar number of calls to setModel and everything probably follows from that. Does rebuildTabs all tabs and restart every time? Note that 1+2+...+33 = 561 which is in the neighborhood (use a 'sum of series calculator')
should rebuildTabs really be called with every new team?

Great results with minimal changes - BUT need to check the results in detail before committing:

Skipping all rebuildTabs calls during load reduces load time from ~30sec to ~2sec. Also need to skip the setting of status color per tab until after load is finished. Added the 'if not self.loadflag' conditional in these two places:

in newEntryProcessTeam:

    if not self.loadFlag:
        self.ui.tabWidget.tabBar().tabButton(i,QTabBar.LeftSide).setStyleSheet(statusStyleDict[status])

in newTeam:

    if not self.loadFlag:
        self.rebuildTabs()

Then in load() after the end of the newEntry loop:

    self.loadFlag=False
    self.rebuildTabs() # since rebuildTabs was disabled when loadFlag was True

For comparison: the load slowness is not new. Tried loading the same file in a radiolog download from May 11 2022 (before the versioning scheme). Load time was 20sec until the progress dialog closed, then another minute or two of unresponsiveness while a truckload of the same headerData tracebacks scrolled by in the transcript. Various lag-related bug fixes since then have probably addressed the lag-after-load quite a bit, but, the slow-load is not new. Regardless, this is the time to fix it.

Looks good - csv written after the fast-load is identical to the csv loaded, except for the overhead statements 'Radiolog started blahblah'. Load time for OP3 of a recent search, with 30 callsigns and 300 entries or so, was 19sec and is now 3sec. Load time for the many-callsigns test case, with 50+ teams was 43.5sec and is now 2.5sec. Calling it good for checklist item 3.

For part 1, a bit of tracing determined that effectively all of that lag (it's only about a second) is inside rebuildTabs. Making an Executive Decision that this is OK and doesn't need to be fixed right now, for a few reasons:

it only happens once per callsign
the delay is only about 1 second at 50 callsigns
the delay is even less for fewer callsigns, but is noticeable starting at about 8 callsigns - so it's not completely negligible
digging deeper into rebuildTabs is not merited right now - but might be merited later in a separate issue

So - closing this issue as 'fixed' for now.

ncssar / radiolog

new lag issues Jan 2023 #623