Bug 3752

Summary: Регресс в 1.0.10 - медленный запуск программ.
Product: WINE@Etersoft Reporter: Антон Азанов (Djelf) <aae>
Component: ОбщееAssignee: Александр Морозов <amorozov>
Status: CLOSED LATER QA Contact: Денис Баранов <baraka>
Severity: minor    
Priority: P3 CC: amorozov, lav
Version: 1.0.10   
Target Milestone: ---   
Hardware: PC   
OS: Ubuntu   
Whiteboard:
Заявки RT: Связано с:
Дата напоминания:
Bug Depends on: 3800    
Bug Blocks: 3589    

Description Антон Азанов (Djelf) 2009-03-30 16:35:38 MSD
На тесте wine@etersoft.sql 1.0.10.15/10 обнаружилось заметное замедление запуска всех программ.

Сравнивались версии wine@etersoft 1.0.8, 1.0.9.43/18 и 1.0.10.15/10
Тестовая платформа 2хAthlon XP, 2Gb, HDD SCSI Fujitsu 30.7G, Ubuntu 7.04
В тестовом скрипте запускался regsvr32 20 раз и каждый раз замерялось время запуска (медленно запускаются все программы, regsvr32 выбран из-за того что, после запуска он сразу же закрывается).
На тестовой платформе средняя скорость запуска regsvr32 на 1.0.8 и 1.0.9.43/18 ~0.7c на 1.0.10.15/10 ~2.9

Первое предположение что виноват winedevice.exe (запускается несколько копий) отпало после его удаления - результат не изменился.

Тест проводился несколько раз с полным удалением и новой установкой wine.
Comment 1 Антон Азанов (Djelf) 2009-04-16 18:31:47 MSD
В wine@etersoft 1.0.10.19/13 скорость запуска приложений исправилась: соответствует 1.0.8 и 1.0.9
Comment 2 Vitaly Lipatov 2009-04-21 20:43:35 MSD
Антон, а по нашим измерениям проблема осталась. См. багу 3800
Comment 3 Антон Азанов (Djelf) 2009-04-22 10:09:46 MSD
Да, все верно, поторопился закрыть, в 13/19 все таки стало быстрее, извиняюсь (на последних тестах был удален winedevice в 1.0.10.13/19).
time regsvr32 (wineserver -p, 2 измерения, первый запуск и повторный)

wine@etersoft 1.0.9.43/18
real    0m1.989s user    0m0.248s sys     0m0.119s
real    0m1.062s user    0m0.224s sys     0m0.121s

wine@etersoft 1.0.10.12/18
real    0m11.417s user    0m1.226s sys     0m0.131s
real    0m2.644s user    0m1.241s sys     0m0.133s

wine@etersoft 1.0.10.13/19
real    0m9.449s user    0m0.543s sys     0m0.127s
real    0m1.433s user    0m0.548s sys     0m0.116s

wine@etersoft 1.0.10.13/19 УДАЛЕНЫ USB драйвера в реестре!
real    0m5.573s user    0m0.537s sys     0m0.124s
real    0m1.326s user    0m0.537s sys     0m0.119s

wine@etersoft 1.0.10.13/19 УДАЛЕН winedevice.exe.so!
real    0m1.878s user    0m0.540s sys     0m0.138s
real    0m1.427s user    0m0.537s sys     0m0.117s

Comment 4 Антон Азанов (Djelf) 2009-04-22 10:48:36 MSD
В предыдущем сообщении, для wine 1.0.10, перепутаны местами открытая/закрытая часть. Следует читать как 1.0.10.18/12 и 1.0.10.19/13
Comment 5 Александр Морозов 2009-04-27 14:45:32 MSD
> Антон, а по нашим измерениям проблема
> осталась. См. багу 3800

Открываю повторно
Comment 6 Александр Морозов 2009-04-27 20:33:49 MSD
Проверил с time -p ww regsvr32 (второй запуск до смерти wineserver).

wine-1.1.20 с USB-патчами (загружаются только mountmgr.sys, usbhub.sys и eusk3usb.sys):
real 2.13  user 0.04  sys 0.10
real 0.60  user 0.03  sys 0.09
wine-etersoft-public из git (закрытая часть sql-1.0.10-alt14), если загружаются только mountmgr.sys, usbhub.sys и eusk3usb.sys:
real 2.97  user 0.13  sys 0.08
real 1.04  user 0.12  sys 0.07
wine-etersoft-public из git (закрытая часть sql-1.0.10-alt14), если загружаются hardlock.sys, mountmgr.sys, parport.sys, sentinel.sys, usbhub.sys, eusk3usb.sys:
real 9.13  user 0.13  sys 0.08
real 1.70  user 0.12  sys 0.07
Comment 7 Александр Морозов 2009-04-28 13:17:19 MSD
wine-etersoft-public из git (закрытая часть sql-1.0.10-alt14),
если загружаются hardlock.sys, mountmgr.sys, parport.sys,
sentinel.sys, usbhub.sys, eusk3usb.sys:
real 9.13  user 0.13  sys 0.08
real 1.70  user 0.12  sys 0.07

Аналогичное измерение на той же машине сегодня:
real 4.24  user 0.11  sys 0.10
real 1.05  user 0.14  sys 0.08
Comment 8 Александр Морозов 2009-04-28 14:09:44 MSD
cellar, time -p ww regsvr32

wine-1.1.20 без загрузки mountmgr.sys:
real 0.69  user 0.04  sys 0.09
real 0.62  user 0.02  sys 0.09
wine-etersoft-public из git без загрузки драйверов:
real 1.52  user 0.14  sys 0.08
real 1.04  user 0.13  sys 0.09
1.0.9-eter42 без загрузки драйверов:
real 1.10  user 0.05  sys 0.08
real 1.04  user 0.04  sys 0.07
Comment 9 Александр Морозов 2009-04-28 14:41:28 MSD
cellar, 1.0.10-eter19/14, time -p regsvr32
real 1.56  user 0.15  sys 0.09
real 1.10  user 0.13  sys 0.10
Если закомментировать проверку лицензии в __wine_kernel_init, то user CPU time заметно уменьшается:
real 1.48  user 0.06  sys 0.08
real 0.98  user 0.06  sys 0.08
Comment 10 Александр Морозов 2009-04-28 14:44:56 MSD
Вообще, получается, что основной вклад в задержку при первом запуске вносят драйверы. Для USB-ключей они загружаются только при наличии ключей, но есть ещё драйверы LPT-ключей и драйверы защиты, которые загружаются независимо от наличия устройств. Было бы неплохо реализовать поддержку установки драйверов. Тогда пользователи будут ставить только те драйверы, которые им нужны, и по умолчанию у них их будет загружаться меньше. Если реализовывать поддержку установки по каким-то причинам не хочется, то можно ещё добавить вкладку в winecfg, позволяющую отключать загрузку определённых драйверов.
Comment 11 Vitaly Lipatov 2009-04-28 19:05:49 MSD
(In reply to comment #10)
> Вообще, получается, что основной вклад в
> задержку при первом запуске вносят
> драйверы. Для USB-ключей они загружаются
Нельзя ли реализовать некую отложенность загрузки
драйверов, или её параллельность?
...
> устройств. Было бы неплохо реализовать
> поддержку установки драйверов. Тогда
Это неплохо, но не столь критично, и потом, нам не очень сейчас нужны произвольные драйвера, которые мы не проверяли.

> пользователи будут ставить только те
> драйверы, которые им нужны, и по умолчанию у
> них их будет загружаться меньше. Если
> реализовывать поддержку установки по
> каким-то причинам не хочется, то можно ещё
> добавить вкладку в winecfg, позволяющую
> отключать загрузку определённых
> драйверов.
Я бы смотрел тогда в сторону предварительного запуска
wineserver -p
То есть первый раз стартуем медленно и полностью, но зато потом - только программу запускаем. А это время тоже увеличилось с 0.4 сек до 2 сек.
Наверное стоит для начала с этим разобраться.

Comment 12 Александр Морозов 2009-04-28 19:13:46 MSD
> Нельзя ли реализовать некую отложенность
> загрузки
> драйверов, или её параллельность?

Раньше так и было. Но при этом возникают ситуации, когда программы стартуют раньше драйвера ключа и ключ не видят. ИМХО, это ещё хуже, чем медленный старт.
Comment 13 Александр Морозов 2009-05-04 15:55:03 MSD
$ cat main.c
int main()
{
        return 0;
}

Повторный запуск на 1.0.10:
$ time -p ww main.exe
loader/main.c:main 1241432866 sec 438218 usec
loader/main.c:main 1241432866 sec 440493 usec
wine_init: 1241432866 sec 440958 usec
fixme:module:__wine_process_init 1241432866 sec 442280 usec
fixme:process:__wine_kernel_init 1241432866 sec 481783 usec
fixme:module:LdrInitializeThunk 1241432866 sec 655892 usec
fixme:server:server_init_process_done BEGIN 1241432866 sec 656466 usec
fixme:server:server_init_process_done END 1241432866 sec 656771 usec
fixme:module:attach_process_dlls 1241432866 sec 659176 usec
fixme:virtual:virtual_clear_thread_stack 1241432866 sec 668379 usec
fixme:process:start_process 1241432866 sec 668717 usec
real 0.28
user 0.13
sys 0.02

Повторный запуск на wine-1.1.20:
$ time -p ww main.exe
loader/main.c:main 1241437515 sec 292657 usec
loader/main.c:main 1241437515 sec 311696 usec
wine_init: 1241437515 sec 312184 usec
fixme:module:__wine_process_init 1241437515 sec 319822 usec
fixme:process:__wine_kernel_init 1241437515 sec 346022 usec
fixme:module:LdrInitializeThunk 1241437515 sec 350858 usec
fixme:server:server_init_process_done BEGIN 1241437515 sec 351681 usec
fixme:server:server_init_process_done END 1241437515 sec 351991 usec
fixme:module:attach_process_dlls 1241437515 sec 356187 usec
fixme:virtual:virtual_clear_thread_stack 1241437515 sec 362536 usec
fixme:process:start_process 1241437515 sec 362891 usec
real 0.12
user 0.02
sys 0.02

Повторный запуск на 1.0.10 с закомментированным кодом проверки лицензии:
$ time -p ww main.exe
loader/main.c:main 1241437779 sec 110123 usec
loader/main.c:main 1241437779 sec 128595 usec
wine_init: 1241437779 sec 129073 usec
fixme:module:__wine_process_init 1241437779 sec 130327 usec
fixme:process:__wine_kernel_init 1241437779 sec 167668 usec
fixme:module:LdrInitializeThunk 1241437779 sec 185406 usec
fixme:server:server_init_process_done BEGIN 1241437779 sec 186010 usec
fixme:server:server_init_process_done END 1241437779 sec 186336 usec
fixme:module:attach_process_dlls 1241437779 sec 188401 usec
fixme:virtual:virtual_clear_thread_stack 1241437779 sec 196867 usec
fixme:process:start_process 1241437779 sec 197222 usec
real 0.13
user 0.02
sys 0.00

Измерения времени проводились на atlant. Кроме проверки лицензии каких-то различий между нашим и оригинальным wine, влияющих на время повторного запуска, не видно.
Comment 14 Vitaly Lipatov 2009-07-31 11:16:22 MSD
Вкладку в winecfg для управления ключами добавили, по умолчанию загрузку драйверов выключили.
В 1.0.11 время повторного запуска около 1 сек, время первого запуска - около 4-х секунд.