[Bug 21423] New: Visual C++ 2005 slow?

http://bugs.winehq.org/show_bug.cgi?id=21423

Summary: Visual C++ 2005 slow?
           Product: Wine
           Version: 1.1.36
          Platform: x86
        OS/Version: Linux
            Status: NEW
          Keywords: download
          Severity: normal
          Priority: P2
         Component: -unknown
        AssignedTo: [e-mail]
        ReportedBy: [e-mail]

See http://bugs.winehq.org/show_bug.cgi?id=21410 for recipe.

Building chromium's base_unittests.exe seems to take longer
in wine than in vista, so I profiled a bit with oprofile:
   583087 43.4516 no-vmlinux
   320289 23.8679 c1xx.dll
   149572 11.1461 ntdll.dll.so
    80027  5.9636 libc-2.10.1.so
    48005  3.5773 libwine.so.1.0
    32901  2.4518 msvcr80.dll
    25959  1.9345 advapi32.dll.so
    22550  1.6804 rpcrt4.dll.so
    13959  1.0402 c2.dll
    13660  1.0179 wineserver

Good Lord, that's a lot of kernel time...

I'll see if I can get a breakdown of the kernel time, have to work around 
https://bugs.launchpad.net/ubuntu/+source/linux/+bug/289087
first.

In the meantime, here's the breakdown inside ntdll:

54636    17.9328  RtlUpcaseUnicodeString
52607    17.2668  hash_short_file_name
37324    12.2506  RtlIsNameLegalDOS8Dot3
15680     5.1465  RtlUpcaseUnicodeStringToCountedOemString
14684     4.8196  find_file_in_dir
11546     3.7897  HEAP_CreateFreeBlock

[Bug 21423] Visual C++ 2005 slow?

http://bugs.winehq.org/show_bug.cgi?id=21423

--- Comment #1 from Dan Kegel   2010-01-23 18:36:43 ---
It takes about an hour to build Chromium on Vista,
but about three hours on Linux + Wine on similar hardware.

Dunno if oprofile is going to help much, but here's what it says.
During one random thirty-second part of a build,
opreport showed
   305924 47.4483 vmlinux-2.6.31-17-generic
    99718 15.4661 ntdll.dll.so
    56680  8.7910 c1xx.dll
    36963  5.7329 wine-preloader
    ...

opreport -l /usr/lib/debug/boot/vmlinux-2.6.31-17-generic showed
 35660    11.6565  ext3fs_dirhash
 28993     9.4772  delay_tsc
 15521     5.0735  str2hashbuf_signed
 14082     4.6031  ext3_htree_store_dirent
 12461     4.0732  copy_to_user
 ...

[Bug 21423] Visual C++ 2005 slow?

http://bugs.winehq.org/show_bug.cgi?id=21423

--- Comment #2 from Dan Kegel   2010-01-28 03:01:52 ---
Created an attachment (id=25916)
 --> (http://bugs.winehq.org/attachment.cgi?id=25916)
script to generate dummy program to compile

[Bug 21423] Visual C++ 2005 slow?

http://bugs.winehq.org/show_bug.cgi?id=21423

--- Comment #3 from Dan Kegel   2010-01-28 03:02:37 ---
It seems that a simple synthetic testcase exhibits a similar 
slowness.   To repeat, run the attached script to generate 
a synthetic C program with 5000 files, then do
  cl -c dummy.c
This takes about 3 seconds on Windows, but about 7 seconds on Wine.

There are probably better test cases, but this is a start.

[Bug 21423] Visual C++ 2005 slow?

http://bugs.winehq.org/show_bug.cgi?id=21423

--- Comment #4 from Dan Kegel   2010-01-28 14:56:21 ---
Created an attachment (id=25927)
 --> (http://bugs.winehq.org/attachment.cgi?id=25927)
add runtime (as opposed to compiletime) microbenchmark

[Bug 21423] Visual C++ 2005 slow?

http://bugs.winehq.org/show_bug.cgi?id=21423

--- Comment #5 from Dan Kegel   2010-01-28 15:10:40 ---
Both the file open (where it's just a trivial C program
opening a lot of trivial files) and file include (where the program is
the C compiler compiling a lot of trivial files) benchmarks 
show about a 2x slowdown on Wine as opposed to Windows on
the same hardware (roughly 2 seconds vs. 1 second).

Adding a Sleep(0) to the beginning of CreateFile() in kernel32 did
not change the results much.  Adding Sleep(1) (which may
involve several wineserver round-trips) resulted in a 6x
slowdown in both benchmarks.

This seems consistent with "file opens are slow in Wine" and with
the high CPU report for wineserver in 'top' (which I guess is mostly
system time, judging by oprofile).

Well, well, Mr. Bond.  How do you expect to speed that up?

[Bug 21423] Visual C++ 2005 slow?

http://bugs.winehq.org/show_bug.cgi?id=21423

--- Comment #6 from Dan Kegel   2010-01-30 23:39:22 ---
For what it's worth, I ran the compiler with +relay and
counted function calls between the lines where two
different input .cc files were opened.  Here are all
the ones that happened more than 100 times:

139 KERNEL32.WideCharToMultiByte
    175 KERNEL32.GetFullPathNameW
    175 KERNEL32.GetVersion
    190 KERNEL32.VirtualAlloc
    228 KERNEL32.FindResourceW
    228 KERNEL32.LoadResource
    240 KERNEL32.InterlockedDecrement
    257 KERNEL32.InterlockedIncrement
    291 KERNEL32.WriteFile
    310 KERNEL32.LCMapStringW
    772 KERNEL32.ReadFile
    869 ntdll.NtCurrentTeb
   1586 KERNEL32.SetFilePointer
   2475 KERNEL32.GetFileAttributesW
   2608 ntdll.RtlFreeHeap
   2701 ntdll.RtlAllocateHeap
   2923 KERNEL32.GetProcessHeap
  17332 KERNEL32.SetLastError
  17351 KERNEL32.FlsGetValue
  17370 KERNEL32.TlsGetValue
  19707 KERNEL32.GetLastError

[Bug 21423] Visual C++ 2005 slow?

http://bugs.winehq.org/show_bug.cgi?id=21423

Uwe Bonnes  changed:

What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |[e-mail]-
                   |                            |darmstadt.de

--- Comment #7 from Uwe Bonnes   2010-01-31 06:33:28 ---
Is some directory with many files involved?

Our hashing algorithm for the DOS name scales badly, at least last I saw that
on some occasions.

[Bug 21423] Visual C++ 2005 slow?

http://bugs.winehq.org/show_bug.cgi?id=21423

--- Comment #8 from Dan Kegel   2010-01-31 18:35:04 ---
Yes.  There is one directory with 1900 files in it.
Using http://www.winehq.org/pipermail/wine-patches/2008-June/056508.html
and then doing WINEDEBUG=+timestamps,+file, I could
see that searching that directory for any particular file 
takes as long as 3ms, as measured by the time it took between

trace:file:wine_nt_to_unix_file_name L"\Program Files\Microsoft
SDKs\Windows\v7.0\Include\typeinfo" not found in
/home/dank/.wine-chromium-tests/dosdevices/c:/Program Files/Microsoft
SDKs/Windows/v7.0/Include

and the trace message immediately before it.

Furthermore, adding a kludgy bloom filter cache to GetFileAttributesW
halved the time to compile base (from 43 seconds to 24 seconds),
so that's definitely the sore spot.  I'll attach the bloom filter patch,
but it's a total kludge, so it's only good for demonstrating the bottleneck.

[Bug 21423] Visual C++ 2005 slow?

http://bugs.winehq.org/show_bug.cgi?id=21423

--- Comment #9 from Dan Kegel   2010-01-31 18:35:46 ---
Created an attachment (id=25991)
 --> (http://bugs.winehq.org/attachment.cgi?id=25991)
kludgy bloom filter to speed up file-not-found checks

[Bug 21423] Visual C++ 2005 slow?

http://bugs.winehq.org/show_bug.cgi?id=21423

--- Comment #10 from Dan Kegel   2010-01-31 20:00:31 ---
Created an attachment (id=25992)
 --> (http://bugs.winehq.org/attachment.cgi?id=25992)
microbenchmark to just call GetFileAttributes on files from stdin

[Bug 21423] Visual C++ 2005 slow?

http://bugs.winehq.org/show_bug.cgi?id=21423

--- Comment #11 from Dan Kegel   2010-01-31 20:04:45 ---
Created an attachment (id=25993)
 --> (http://bugs.winehq.org/attachment.cgi?id=25993)
Microbenchmark input data

This microbenchmark replicates the access pattern of cl when compiling
one particular file from chromium/base.
Run it like this:
  sh winetricks vc2005trial psdkwin7
  i586-mingw32msvc-gcc open.c
  time wine a.exe < open.in
It runs in 0.3 seconds normally on Wine, but 0.2 seconds with the bloom filter
patch applied.  I think that's enough to explain at least part of the slowdown.

[Bug 21423] Visual C++ 2005 slow?

http://bugs.winehq.org/show_bug.cgi?id=21423

--- Comment #12 from Dan Kegel   2010-01-31 21:22:42 ---
Created an attachment (id=25994)
 --> (http://bugs.winehq.org/attachment.cgi?id=25994)
Minibenchmark part 1

[Bug 21423] Visual C++ 2005 slow?

http://bugs.winehq.org/show_bug.cgi?id=21423

Dan Kegel  changed:

What    |Removed                     |Added
----------------------------------------------------------------------------
  Attachment #25994|0                           |1
        is obsolete|                            |

[Bug 21423] Visual C++ 2005 slow?

http://bugs.winehq.org/show_bug.cgi?id=21423

--- Comment #13 from Dan Kegel   2010-01-31 23:33:56 ---
This bug is about cl.exe being slow when given an .rsp file with
lots of .cc files in it, as devenv does.  
(In that case, cl's startup time doesn't matter much,
since it only has to start once for that whole batch of files.)

See bug 21566 for cl.exe being slow to start up
(which matters when starting cl.exe once for each input file, as make does).

[Bug 21423] Visual C++ 2005 slow?

http://bugs.winehq.org/show_bug.cgi?id=21423

--- Comment #14 from Uwe Bonnes   2010-02-01 03:42:45 ---
Is the "kludgy bloom filter" intended to get included in wine. Then you should
send it to [e-mail], so Alexandre could notice ( and probably
will put hit "pending" mark on it ;-))

[Bug 21423] Visual C++ 2005 slow?

http://bugs.winehq.org/show_bug.cgi?id=21423

--- Comment #15 from Dan Kegel   2010-02-01 07:40:34 ---
No, it's just to show where the bottleneck is, it breaks some apps as is.

[Bug 21423] Visual C++ 2005 slow?

http://bugs.winehq.org/show_bug.cgi?id=21423

Sylvain Petreolle  changed:

What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |[e-mail]

[Bug 21423] Visual C++ 2005 slow?

http://bugs.winehq.org/show_bug.cgi?id=21423

--- Comment #16 from [e-mail] 2013-06-27 12:36:57 CDT ---
This ticket has not been updated for over 900 days.

Is this still an issue in wine version 1.6-rc3 or higher or is this to be
closed as abandoned ?

[Bug 21423] Visual C++ 2005 slow?

[WineHQ Bugzilla]

https://bugs.winehq.org/show_bug.cgi?id=21423

joaopa  changed:

What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |[e-mail]

--- Comment #17 from joaopa  ---
Does the bug still occur with wine-5.6?