Strange GUI delays

Please report only one bug per message!

Moderators: white, Hacker, petermad, Stefan2

coder_x86
Junior Member
Junior Member
Posts: 3
Joined: 2010-02-20, 21:56 UTC
Location: Ukraine

Strange GUI delays

Post by *coder_x86 »

A few days ago I've installed Total Commander v7.50a. All new features are really awesome and everything would be cool if new TC didn't become slower in comparison with previous v7.04a version in such basic operations as creating and deleting folders! I mean that the GUI is now less responsive. For example, when I create a new empty folder I can see that it appears in the list only after a short delay and it feels like it has to redraw something complicated. The same thing when deleting files/folders, sometimes it is even possible to notice a slight flicker. In v7.04a I could produce a series of {Del, Enter} keystrokes in less than a second and it worked immediately - file list was redrawn in almost no time.

I made a small investigation using Process Monitor on a clean Windows XP SP3 (x86) installation in VMWare v7.0 with the default installation of TC v7.50a and v7.04a and it looks like there is a problem in a new TC itself. Please notice a strange ~100ms delay on the following screenshots for v7.50a when creating and deleting an empty "test" folder which takes place right after an actual file operation has been carried out, but before refreshing the list of files.

v7.50a creating test folder:
Image: http://i2.fastpic.ru/big/2010/0222/78/d05e3a93d3ff64ae90b58255f41f6378.png

v7.50a deleting test folder:
Image: http://i2.fastpic.ru/big/2010/0222/38/eafc96b49db7eb61a81df98ebf726e38.png

Process Monitor also revealed that the total time required to perform create/delete folder operation considerably increased, even taking into account this strange delay, for my PC these values are:
v7.04a: creates test folder in ~45ms, deletes in ~85ms
v7.50a: creates in ~230ms (would be ~130ms w/o delay), deletes in ~175ms (~75ms w/o delay)

Can anybody advise something about how to resolve this annoying bug/feature? I tried searching the forum, but didn't find anything like that.
User avatar
ghisler(Author)
Site Admin
Site Admin
Posts: 48021
Joined: 2003-02-04, 09:46 UTC
Location: Switzerland
Contact:

Post by *ghisler(Author) »

Unfortunately I cannot reproduce the problem here. Can anyone else reproduce it?
Author of Total Commander
https://www.ghisler.com
User avatar
MVV
Power Member
Power Member
Posts: 8702
Joined: 2008-08-03, 12:51 UTC
Location: Russian Federation

Post by *MVV »

I think I may confirm that 7.04a creates and goes to created folder more quickly than 7.50a - it seems to be so.

You may try to open both TC versions in same folder and to create some new folders in both TCs in order to see reaction speed.
Sob
Power Member
Power Member
Posts: 941
Joined: 2005-01-19, 17:33 UTC

Post by *Sob »

I'm joining the investigation. :) I see it here and you can too, thanks to nice little program called CamStudio:

http://www.volny.cz/sobosh/tc-mkdir.avi (1.1MB)

Left is TC 7.04, right is TC 7.50a, running side by side under Windows 7 x64.

Text description:

(1 frame in video is 5ms)

TC 7.04:

02.990 - create directory dialog is visible and has focus
02.995 - dialog closed, area where it covered file list is blank (background color), other parts of file list are visible
(nothing for next 15ms)
03.010 - all done, folder created, file list is fully repainted

total time = ~20ms

TC 7.50a:

05.545 - create directory dialog is visible and has focus
05.550 - dialog loses focus (not always visible)
05.570 - dialog closed, whole file list gets painted with background color
(nothing for next 105ms - every time it's about 100ms)
05.675 - first lone icon is painted in file list
(nothing for next 110ms - not always, I'd say it's 75% chance to be about 100ms or about 5ms)
05.785 - file list is fully repainted

total time = ~240ms (always at least 150ms)
Sob
Power Member
Power Member
Posts: 941
Joined: 2005-01-19, 17:33 UTC

Post by *Sob »

I tried some more with clean Windows XP SP3 x86 in VirtualBox. Following are logs from Process Monitor, showing the part when the delay occurs. TC was started with clean ini file and only two panels (C:\Temp\!tctest in left, C:\ in right), no other tabs.

TC 7.04: 2.4ms, almost instant

Code: Select all

"Time of Day","Process Name","PID","Operation","Path","Result","Detail"
"0:37:04,4982018","tc704.exe","1972","CreateFile","C:\Temp\!tctest\test704","SUCCESS","Desired Access: Read Data/List Directory, Synchronize, Disposition: Create, Options: Directory, Synchronous IO Non-Alert, Attributes: N, ShareMode: Read, Write, AllocationSize: 0, OpenResult: Created"
"0:37:04,4990564","tc704.exe","1972","CloseFile","C:\Temp\!tctest\test704","SUCCESS",""
"0:37:04,4990948","tc704.exe","1972","IRP_MJ_CLOSE","C:\Temp\!tctest\test704","SUCCESS",""
"0:37:04,4995616","tc704.exe","1972","CreateFile","C:\Temp\!tctest\test704","SUCCESS","Desired Access: Execute/Traverse, Synchronize, Disposition: Open, Options: Directory, Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, AllocationSize: n/a, OpenResult: Opened"
"0:37:04,4996260","tc704.exe","1972","CloseFile","C:\Temp\!tctest","SUCCESS",""
"0:37:04,4996601","tc704.exe","1972","IRP_MJ_CLOSE","C:\Temp\!tctest","SUCCESS",""
"0:37:04,4999325","tc704.exe","1972","CreateFile","C:\treeinfo.wc","NAME NOT FOUND","Desired Access: Generic Read, Disposition: Open, Options: Sequential Access, Synchronous IO Non-Alert, Non-Directory File, Attributes: n/a, ShareMode: None, AllocationSize: n/a"
"0:37:04,5003341","tc704.exe","1972","CreateFile","C:\","SUCCESS","Desired Access: Read Data/List Directory, Synchronize, Disposition: Open, Options: Directory, Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, AllocationSize: n/a, OpenResult: Opened"
"0:37:04,5003920","tc704.exe","1972","QueryDirectory","C:\*","SUCCESS","Filter: *, 1: AUTOEXEC.BAT"
"0:37:04,5005092","tc704.exe","1972","CreateFile","C:\","SUCCESS","Desired Access: Execute/Traverse, Synchronize, Disposition: Open, Options: Directory, Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, AllocationSize: n/a, OpenResult: Opened"
"0:37:04,5005712","tc704.exe","1972","CloseFile","C:\Temp\!tctest\test704","SUCCESS",""
"0:37:04,5006143","tc704.exe","1972","IRP_MJ_CLOSE","C:\Temp\!tctest\test704","SUCCESS",""
TC 7.50a: 106ms, huge difference

Code: Select all

"Time of Day","Process Name","PID","Operation","Path","Result","Detail"
"0:37:06,3749941","tc750a.exe","544","CreateFile","C:\Temp\!tctest\test750a","SUCCESS","Desired Access: Read Data/List Directory, Synchronize, Disposition: Create, Options: Directory, Synchronous IO Non-Alert, Attributes: N, ShareMode: Read, Write, AllocationSize: 0, OpenResult: Created"
"0:37:06,3764225","tc750a.exe","544","CloseFile","C:\Temp\!tctest\test750a","SUCCESS",""
"0:37:06,3765016","tc750a.exe","544","IRP_MJ_CLOSE","C:\Temp\!tctest\test750a","SUCCESS",""
"0:37:06,3774983","tc750a.exe","544","CreateFile","C:\Temp\!tctest\test750a","SUCCESS","Desired Access: Execute/Traverse, Synchronize, Disposition: Open, Options: Directory, Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, AllocationSize: n/a, OpenResult: Opened"
"0:37:06,3776326","tc750a.exe","544","CloseFile","C:\Temp\!tctest","SUCCESS",""
"0:37:06,3777047","tc750a.exe","544","IRP_MJ_CLOSE","C:\Temp\!tctest","SUCCESS",""
"0:37:06,4466360","tc750a.exe","544","CloseFile","C:\","SUCCESS",""
"0:37:06,4467140","tc750a.exe","544","IRP_MJ_CLOSE","C:\","SUCCESS",""
"0:37:06,4794521","tc750a.exe","544","CreateFile","C:\","SUCCESS","Desired Access: Read Data/List Directory, Synchronize, Disposition: Open, Options: Directory, Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, AllocationSize: n/a, OpenResult: Opened"
"0:37:06,4797420","tc750a.exe","544","QueryDirectory","C:\*","SUCCESS","Filter: *, 1: AUTOEXEC.BAT"
"0:37:06,4802256","tc750a.exe","544","CreateFile","C:\","SUCCESS","Desired Access: Execute/Traverse, Synchronize, Disposition: Open, Options: Directory, Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, AllocationSize: n/a, OpenResult: Opened"
"0:37:06,4804654","tc750a.exe","544","CloseFile","C:\Temp\!tctest\test750a","SUCCESS",""
"0:37:06,4805778","tc750a.exe","544","IRP_MJ_CLOSE","C:\Temp\!tctest\test750a","SUCCESS",""
This might provide some clue, TC 7.50a, Windows 7 x64

Code: Select all

"Time of Day","Process Name","PID","Operation","Path","Result","Detail"
"0:42:15,0151043","tc750a.exe","2900","CreateFile","C:\Temp\!tctest\test750a","SUCCESS","Desired Access: Read Data/List Directory, Synchronize, Disposition: Create, Options: Directory, Synchronous IO Non-Alert, Open Reparse Point, Attributes: N, ShareMode: Read, Write, AllocationSize: 0, OpenResult: Created"
"0:42:15,0152510","tc750a.exe","2900","CloseFile","C:\Temp\!tctest\test750a","SUCCESS",""
"0:42:15,0152844","tc750a.exe","2900","IRP_MJ_CLOSE","C:\Temp\!tctest\test750a","SUCCESS",""
"0:42:15,0153738","tc750a.exe","2900","CreateFile","C:\Temp\!tctest\test750a","SUCCESS","Desired Access: Execute/Traverse, Synchronize, Disposition: Open, Options: Directory, Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, AllocationSize: n/a, OpenResult: Opened"
"0:42:15,0154038","tc750a.exe","2900","CloseFile","C:\Temp\!tctest","SUCCESS",""
"0:42:15,0154214","tc750a.exe","2900","IRP_MJ_CLOSE","C:\Temp\!tctest","SUCCESS",""
"0:42:15,0476996","tc750a.exe","2900","CloseFile","C:\","SUCCESS",""
"0:42:15,0477261","tc750a.exe","2900","IRP_MJ_CLOSE","C:\","SUCCESS",""
"0:42:15,0515261","tc750a.exe","2900","CreateFile","\\zrout\e$\","SUCCESS","Desired Access: Read Data/List Directory, Read Attributes, Synchronize, Disposition: Open, Options: , Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"0:42:15,0537358","tc750a.exe","2900","CloseFile","\\zrout\e$\","SUCCESS",""
"0:42:15,0537838","tc750a.exe","2900","IRP_MJ_CLOSE","\\zrout\e$\","SUCCESS",""
"0:42:15,1148504","tc750a.exe","2900","CreateFile","C:\","SUCCESS","Desired Access: Read Data/List Directory, Synchronize, Disposition: Open, Options: Directory, Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened"
"0:42:15,1149096","tc750a.exe","2900","QueryDirectory","C:\*","SUCCESS","Filter: *, 1: $Recycle.Bin"
"0:42:15,1149602","tc750a.exe","2900","QueryDirectory","C:\","SUCCESS","0: Boot, 1: CardReader, 2: cygwin, 3: Documents and Settings, 4: Program Files, 5: Program Files (x86), 6: ProgramData, 7: Recovery, 8: System Volume Information, 9: Temp, 10: Users, 11: Windows"
"0:42:15,1151852","tc750a.exe","2900","CreateFile","C:\","SUCCESS","Desired Access: Execute/Traverse, Synchronize, Disposition: Open, Options: Directory, Synchronous IO Non-Alert, Attributes: n/a, ShareMode: Read, Write, AllocationSize: n/a, OpenResult: Opened"
"0:42:15,1152559","tc750a.exe","2900","CloseFile","C:\Temp\!tctest\test750a","SUCCESS",""
"0:42:15,1152985","tc750a.exe","2900","IRP_MJ_CLOSE","C:\Temp\!tctest\test750a","SUCCESS",""
For some reason TC accesses the network share. But this path is not opened in TC, it's just mapped as network drive T: which is also not opened in TC. Also three more network drives exist in system. So there is no reason why TC would access just this one.
Around the same place where is the network drive access, TC (7.50a only) also accessed c:\Windows\CSC\<somelongerpath>. It stopped when I turned off "Offline files" in Windows.
coder_x86
Junior Member
Junior Member
Posts: 3
Joined: 2010-02-20, 21:56 UTC
Location: Ukraine

Post by *coder_x86 »

The trick is that these delays are present anyways, it doesn't matter have you any net drives connected or not and whether offline files are turned on or off. Process Monitor logs just prove that these delays aren't related to file operations and their quantity, but rather to some synchronization timeout or GUI update/redraw stuff. I even tried to kill all TC's worker threads with Process Explorer (except the main thread and one which gets automatically restarted by TC) to check if that might be caused by some background activity, but that didn't speed things up anyways. So my guess is that it is related to increased amounts of work related to repainting of UI elements and probably this issue can be resolved only with help of some advanced process profiling and debugging techniques/utilities...
User avatar
Lefteous
Power Member
Power Member
Posts: 9535
Joined: 2003-02-09, 01:18 UTC
Location: Germany
Contact:

Post by *Lefteous »

There is a hint to the treefile in Sob's log. Maybe the separate tree in involved as well.
User avatar
ghisler(Author)
Site Admin
Site Admin
Posts: 48021
Joined: 2003-02-04, 09:46 UTC
Location: Switzerland
Contact:

Post by *ghisler(Author) »

Hmm, no clue yet - doesn't look like a separate tree problem...
Author of Total Commander
https://www.ghisler.com
cheming
Member
Member
Posts: 153
Joined: 2004-05-07, 14:38 UTC
Location: China

Post by *cheming »

I also find that TC's repaint speed is too slow. You can see this when you minimize and restore a TC windows. The filelist window flashed when you do that.
User avatar
ghisler(Author)
Site Admin
Site Admin
Posts: 48021
Joined: 2003-02-04, 09:46 UTC
Location: Switzerland
Contact:

Post by *ghisler(Author) »

The filelist window flashed when you do that.
That's because TC re-reads the file list when you switch away from it and back! You can turn that off for slow drives in Configuration - Options - Refresh (upper part) by listing the slow drives there, and/or a backslash for paths without drive letter. You will have to press F2 or Ctrl+R to cause a manual refresh then.
Author of Total Commander
https://www.ghisler.com
liborm
Junior Member
Junior Member
Posts: 12
Joined: 2010-03-15, 11:55 UTC

Post by *liborm »

I confirm the notable delay of 7.50 in comparison with 7.04a.
User avatar
ghisler(Author)
Site Admin
Site Admin
Posts: 48021
Joined: 2003-02-04, 09:46 UTC
Location: Switzerland
Contact:

Post by *ghisler(Author) »

Unfortunately I cannot see any delay - to the contrary, TC 7.5 is faster here creating a directory because the directory history is saved in one step (one function call saves the entire section) instead of separate calls to save each directory.

To troubleshoot, try this:
1. Turn off any separate trees if used
2. Turn off icons
3. Delete treeinfo.wc from drive root (hidden file)

Does any of these help?
Author of Total Commander
https://www.ghisler.com
User avatar
MVV
Power Member
Power Member
Posts: 8702
Joined: 2008-08-03, 12:51 UTC
Location: Russian Federation

Post by *MVV »

It is strange but now I can't see difference in folder creation speed - both 7.04a and 7.50a create dir and set focus in similar time delay. But I'm almost sure that I saw such difference last time when I checked it...
Sob
Power Member
Power Member
Posts: 941
Joined: 2005-01-19, 17:33 UTC

Post by *Sob »

ghisler(Author) wrote:Does any of these help?
Made no difference here.

--

This is an attempt for realiable way how to reproduce the issue. So far tested on 5 different systems having nothing in common with same results.

1) create test directories: C:\TCTest\, C:\TCTest\test704\, C:\TCTest\test750a\, C:\TCTest\rightpaneldir\

2) copy TC executables: totalcmd.exe 7.04 to C:\TCTest\tc704.exe, totalcmd.exe 7.50a to C:\TCTest\tc750a.exe

3) run TCs with following command lines:

Code: Select all

c:\TCTest\tc704.exe /i=c:\TCTest\tc704.ini /f=c:\TCTest\ftp704.ini
c:\TCTest\tc750a.exe /i=c:\TCTest\tc750a.ini /f=c:\TCTest\ftp750a.ini
4) settings windows will pop up, because selected ini files don't exist yet, so TCs take it as first run; don't change anything

5) open C:\TCTest\rightpaneldir\ in right panel and C:\TCTest\test704\ in left (or C:\TCTest\test750a\, depending on TC version)

6) start Process Monitor (http://technet.microsoft.com/en-us/sysinternals/bb896645.aspx) and set filter to include Process Name that begins with "tc7".

7) in both TCs create a new directory "newdir" in left panel

8) look for "newdir" in Process Monitor and you should see the exact pattern as in the following pictures; sometimes there may appear other entries mixed in, e.g. accessing the ini file, either ignore them or try creating another directory and there's a chance they won't be there again

http://www.volny.cz/sobosh/tc-mkdir704.png
http://www.volny.cz/sobosh/tc-mkdir750a.png

The entries with green background are exactly same in both versions. But there is something different going on in the middle. There is less than 1ms between end of first green block and beginning of the second in TC 7.04, while it's over 100ms in TC 7.50a.
crmagicxxx
New Member
New Member
Posts: 1
Joined: 2010-04-20, 16:26 UTC

Post by *crmagicxxx »

Just want to confirm same behavior as above. I am using XP. Because my daily work requires frequent switching between commander and other applications, and fast response from commander regarding pre-defined keystrokes and copy/move operations, I was forced to downgrade to 7.04 again. That slight pause in file list refreshment in version 7.50a was just too much for me and I was facing lost keystrokes all the time while commander was refreshing the screen

I hope this will be resolved soon

Best
Post Reply