Bug 48

Summary: 1Cv77: Нагруженность системы потоком сообщений
Product: WINE@Etersoft Reporter: Vitaly Lipatov <lav>
Component: ОбщееAssignee: Анатолий Лютин <vostok>
Status: CLOSED FIXED QA Contact: Vitaly Lipatov <lav>
Severity: critical    
Priority: P2 CC: amorozov, baraka, ti.eugene, triada123, vostok
Version: unspecified   
Target Milestone: ---   
Hardware: PC   
OS: Linux   
Whiteboard:
Заявки RT: Связано с:
Дата напоминания:
Bug Depends on: 591    
Bug Blocks: 42, 363, 2611    

Description Vitaly Lipatov 2006-03-16 00:08:56 MSK 
шмеющимся на экране элементам отправляется слишком много сообщений, что может 
замедлять работу. 
В основном это касается случаев нахождения курсора мыши над панелью 
инструментов (самый критичный случай), также в поле предварительного просмотра 
и просто в диалогах. Нагрузка пропадает, если открыть дополнительное 
стандартное меню (например, в журнале или документе при нажатии кнопки, 
раскрывающейся в список).
Comment 1 Vitaly Lipatov 2006-06-13 19:52:05 MSD 
Обнаружено, что непрерывно посылается WM_GETTEXT элементу Edit (строке поиска) 
 
=>1 0x7fa3f355 EditWndProc_common+0xac5(wParam=0x7fc0e204, lParam=0x7fc0e204, 
unicode=0x0) [/home/lav/Projects/wine/dlls/user/edit.c:900] in user32 
(0x7fa3f355) 
  2 0x7fa40c3a EditWndProcA+0x1a(hWnd=0x10068, uMsg=0xd, wParam=0x2, 
lParam=0x7fc0e204) [/home/lav/Projects/wine/dlls/user/edit.c:1095] in user32 
(0x7fa40c3a) 
  3 0x7fa88b6a WINPROC_wrapper+0x1a in user32 (0x7fa88b6a) 
  4 0x7fa89276 call_window_proc+0x66(hwnd=0x10068, msg=0xd, wp=0x2, 
lp=0x7fc0e204, result=0x7fc0dc28, arg=0x7fa40c20) 
[/home/lav/Projects/wine/dlls/user/winproc.c:452] in user32 (0x7fa89276) 
  5 0x7fa8caa6 CallWindowProcA+0x46(func=0x7fa40c20, hwnd=0x10068, msg=0xd, 
wParam=0x2, lParam=0x7fc0e204) 
[/home/lav/Projects/wine/dlls/user/winproc.c:2227] in user32 (0x7fa8caa6) 
  6 0x6c2920f2 in mfc42 (+0x20f2) (0x6c2920f2) 
  7 0x6c291d01 in mfc42 (+0x1d01) (0x6c291d01) 
  8 0x6c291c73 in mfc42 (+0x1c73) (0x6c291c73) 
  9 0x6c291bfb in mfc42 (+0x1bfb) (0x6c291bfb) 
  10 0x6c291bba in mfc42 (+0x1bba) (0x6c291bba) 
  11 0x7fa88b6a WINPROC_wrapper+0x1a in user32 (0x7fa88b6a) 
  12 0x7fa89276 call_window_proc+0x66(hwnd=0x10068, msg=0xd, wp=0x2, 
lp=0x7fc0e204, result=0x7fc0e460, arg=0x6c291b81) 
[/home/lav/Projects/wine/dlls/user/winproc.c:452] in user32 (0x7fa89276) 
  13 0x7fa8d4ef WINPROC_CallProcWtoA+0x94f(wParam=0x2, lParam=0x7fda25e8, 
result=0x7fc0e460, arg=0x6c291b81) 
[/home/lav/Projects/wine/dlls/user/winproc.c:1093] in user32 (0x7fa8d4ef) 
  14 0x7fa8d9a7 CallWindowProcW+0x97(func=0xffff0025, hwnd=0x10068, msg=0xd, 
wParam=0x2, lParam=0x7fda25e8) 
[/home/lav/Projects/wine/dlls/user/winproc.c:2254] in user32 (0x7fa8d9a7) 
  15 0x7fa5d49e call_window_proc+0x13e(hwnd=<register not in topmost frame>, 
lparam=0x7fda25e8, unicode=0x1, same_thread=0x1) 
[/home/lav/Projects/wine/dlls/user/message.c:1536] in user32 (0x7fa5d49e) 
  16 0x7fa614b6 SendMessageTimeoutW+0x176(hwnd=0x10068, msg=0xd, wparam=0x2, 
lparam=0x7fda25e8, flags=0x0, timeout=0x0, res_ptr=0x7fc0e574) 
[/home/lav/Projects/wine/dlls/user/message.c:2372] in user32 (0x7fa614b6) 
  17 0x7fa61507 SendMessageW+0x37(hwnd=0x10068, msg=0xd, wparam=0x2, 
lparam=0x7fda25e8) [/home/lav/Projects/wine/dlls/user/message.c:2458] in 
user32 (0x7fa61507) 
  18 0x7fa805cc GetWindowTextW+0x3c(hwnd=0x10068, lpString=0x7fda25e8, 
nMaxCount=0x2) [/home/lav/Projects/wine/dlls/user/win.c:2395] in user32 
(0x7fa805cc) 
  19 0x7fa1d7b2 CBUpdateLBox+0x142 
[/home/lav/Projects/wine/dlls/user/combo.c:1022] in user32 (0x7fa1d7b2) 
  20 0x7fa1e09f COMBO_Command+0x26f(lphc=<register not in topmost frame>, 
wParam=<register not in topmost frame>, hWnd=<register not in topmost frame>) 
[/home/lav/Projects/wine/dlls/user/combo.c:1345] in user32 (0x7fa1e09f) 
  21 0x7fa1f807 ComboWndProc_common+0x16d7(hwnd=<register not in topmost 
frame>, message=<register not in topmost frame>, lParam=0x10068, unicode=0x0) 
[/home/lav/Projects/wine/dlls/user/combo.c:1974] in user32 (0x7fa1f807) 
  22 0x7fa20d0b ComboWndProcA+0x3b(hwnd=0x10064, message=0x111, 
wParam=0x30003e9, lParam=0x10068) 
[/home/lav/Projects/wine/dlls/user/combo.c:2338] in user32 (0x7fa20d0b) 
  23 0x7fa88b6a WINPROC_wrapper+0x1a in user32 (0x7fa88b6a) 
  24 0x7fa89276 call_window_proc+0x66(hwnd=0x10064, msg=0x111, wp=0x30003e9, 
lp=0x10068, result=0x7fc0e7dc, arg=0x7fa20cd0) 
[/home/lav/Projects/wine/dlls/user/winproc.c:452] in user32 (0x7fa89276) 
  25 0x7fa8caa6 CallWindowProcA+0x46(func=0x7fa20cd0, hwnd=0x10064, msg=0x111, 
wParam=0x30003e9, lParam=0x10068) 
[/home/lav/Projects/wine/dlls/user/winproc.c:2227] in user32 (0x7fa8caa6) 
  26 0x6c2920f2 in mfc42 (+0x20f2) (0x6c2920f2) 
  27 0x6c291d01 in mfc42 (+0x1d01) (0x6c291d01) 
  28 0x6c291c73 in mfc42 (+0x1c73) (0x6c291c73) 
  29 0x6c291bfb in mfc42 (+0x1bfb) (0x6c291bfb) 
  30 0x6c291bba in mfc42 (+0x1bba) (0x6c291bba) 
  31 0x7fa88b6a WINPROC_wrapper+0x1a in user32 (0x7fa88b6a) 
  32 0x7fa89276 call_window_proc+0x66(hwnd=0x10064, msg=0x111, wp=0x30003e9, 
lp=0x10068, result=0x7fc0f014, arg=0x6c291b81) 
[/home/lav/Projects/wine/dlls/user/winproc.c:452] in user32 (0x7fa89276) 
  33 0x7fa8ccd9 WINPROC_CallProcWtoA+0x139(wParam=0x30003e9, lParam=0x10068, 
result=0x7fc0f014, arg=0x6c291b81) 
[/home/lav/Projects/wine/dlls/user/winproc.c:1127] in user32 (0x7fa8ccd9) 
  34 0x7fa8d9a7 CallWindowProcW+0x97(func=0xffff0025, hwnd=0x10064, msg=0x111, 
wParam=0x30003e9, lParam=0x10068) 
[/home/lav/Projects/wine/dlls/user/winproc.c:2254] in user32 (0x7fa8d9a7) 
  35 0x7fa5d49e call_window_proc+0x13e(hwnd=<register not in topmost frame>, 
lparam=0x10068, unicode=0x1, same_thread=0x1) 
[/home/lav/Projects/wine/dlls/user/message.c:1536] in user32 (0x7fa5d49e) 
  36 0x7fa614b6 SendMessageTimeoutW+0x176(hwnd=0x10064, msg=0x111, 
wparam=0x30003e9, lparam=0x10068, flags=0x0, timeout=0x0, res_ptr=0x7fc0f128) 
[/home/lav/Projects/wine/dlls/user/message.c:2372] in user32 (0x7fa614b6) 
  37 0x7fa61507 SendMessageW+0x37(hwnd=0x10064, msg=0x111, wparam=0x30003e9, 
lparam=0x10068) [/home/lav/Projects/wine/dlls/user/message.c:2458] in user32 
(0x7fa61507) 
  38 0x7fa3cc0e EDIT_EM_ReplaceSel+0x1ce(es=<register not in topmost frame>, 
send_update=0x1, honor_limit=0x1) 
[/home/lav/Projects/wine/dlls/user/edit.c:3364] in user32 (0x7fa3cc0e) 
  39 0x7fa3e1c8 EDIT_WM_Char+0x78(es=<register not in topmost frame>, 
c=<register not in topmost frame>) 
[/home/lav/Projects/wine/dlls/user/edit.c:4041] in user32 (0x7fa3e1c8) 
  40 0x7fa3ee9f EditWndProc_common+0x60f(wParam=<register not in topmost 
frame>, lParam=0x20001, unicode=0x0) 
[/home/lav/Projects/wine/dlls/user/edit.c:838] in user32 (0x7fa3ee9f) 
  41 0x7fa40c3a EditWndProcA+0x1a(hWnd=0x10068, uMsg=0x102, wParam=0x21, 
lParam=0x20001) [/home/lav/Projects/wine/dlls/user/edit.c:1095] in user32 
(0x7fa40c3a) 
  42 0x7fa88b6a WINPROC_wrapper+0x1a in user32 (0x7fa88b6a) 
  43 0x7fa89276 call_window_proc+0x66(hwnd=0x10068, msg=0x102, wp=0x21, 
lp=0x20001, result=0x7fc0f350, arg=0x7fa40c20) 
[/home/lav/Projects/wine/dlls/user/winproc.c:452] in user32 (0x7fa89276) 
  44 0x7fa8caa6 CallWindowProcA+0x46(func=0x7fa40c20, hwnd=0x10068, msg=0x102, 
wParam=0x21, lParam=0x20001) 
[/home/lav/Projects/wine/dlls/user/winproc.c:2227] in user32 (0x7fa8caa6) 
  45 0x6c2920f2 in mfc42 (+0x20f2) (0x6c2920f2) 
  46 0x6c291d01 in mfc42 (+0x1d01) (0x6c291d01) 
  47 0x6c291c73 in mfc42 (+0x1c73) (0x6c291c73) 
  48 0x6c291bfb in mfc42 (+0x1bfb) (0x6c291bfb) 
  49 0x6c291bba in mfc42 (+0x1bba) (0x6c291bba) 
  50 0x7fa88b6a WINPROC_wrapper+0x1a in user32 (0x7fa88b6a) 
  51 0x7fa89276 call_window_proc+0x66(hwnd=0x10068, msg=0x102, wp=0x21, 
lp=0x20001, result=0x7fc0fb88, arg=0x6c291b81) 
[/home/lav/Projects/wine/dlls/user/winproc.c:452] in user32 (0x7fa89276) 
  52 0x7fa8ccd9 WINPROC_CallProcWtoA+0x139(wParam=0x21, lParam=0x20001, 
result=0x7fc0fb88, arg=0x6c291b81) 
[/home/lav/Projects/wine/dlls/user/winproc.c:1127] in user32 (0x7fa8ccd9) 
  53 0x7fa8d9a7 CallWindowProcW+0x97(func=0xffff0025, hwnd=0x10068, msg=0x102, 
wParam=0x21, lParam=0x20001) 
[/home/lav/Projects/wine/dlls/user/winproc.c:2254] in user32 (0x7fa8d9a7) 
  54 0x7fa5d8f5 DispatchMessageW+0x155(msg=0x7fc0fd5c) 
[/home/lav/Projects/wine/dlls/user/message.c:3040] in user32 (0x7fa5d8f5) 
  55 0x7fa32f61 IsDialogMessageW+0xf1(hwndDlg=0x10056, msg=0x7fc0fd5c) 
[/home/lav/Projects/wine/dlls/user/dialog.c:1190] in user32 (0x7fa32f61) 
  56 0x7fa5d610 IsDialogMessageA+0x40(hwndDlg=0x10056, pmsg=0x43611c) 
[/home/lav/Projects/wine/dlls/user/message.c:2873] in user32 (0x7fa5d610) 
  57 0x6c2a690f in mfc42 (+0x1690f) (0x6c2a690f) 
  58 0x6c291448 in mfc42 (+0x1448) (0x6c291448) 
  59 0x00000102 (0x00000102) 
  60 0x00000000 (0x00000000) 
0x7fa3f355 EditWndProc_common+0xac5 
[/home/lav/Projects/wine/dlls/user/edit.c:900] in user32: movb      
$0x0,0x00000000 
900                             t=0,*t=0;
Comment 2 Vitaly Lipatov 2006-06-13 19:54:25 MSD 
Это только при показе окна с новостями
Comment 3 Vitaly Lipatov 2006-06-14 21:53:15 MSD 
При простое длинный цикл таких сообщений: 
GET:swqrsafx 
GET:swqrsafx 
trace:tab:TAB_WindowProc hwnd=0x501b0 msg=363 wParam=1 lParam=0 
trace:tab:TAB_WindowProc hwnd=0x501b0 msg=363 wParam=1 lParam=0 
trace:tab:TAB_WindowProc hwnd=0x30206 msg=130c wParam=0 lParam=0 
trace:tab:TAB_SetCurSel infoPtr=0x7d7c4968, iSelected=0, iItem=0, uNumItem=1 
trace:tab:TAB_WindowProc hwnd=0x30206 msg=363 wParam=1 lParam=0 
GET:swqrsafx 
GET:swqrsafx 
trace:tab:TAB_WindowProc hwnd=0x501b0 msg=363 wParam=1 lParam=0 
trace:tab:TAB_WindowProc hwnd=0x501b0 msg=363 wParam=1 lParam=0 
trace:tab:TAB_WindowProc hwnd=0x30206 msg=130c wParam=0 lParam=0 
trace:tab:TAB_SetCurSel infoPtr=0x7d7c4968, iSelected=0, iItem=0, uNumItem=1 
trace:tab:TAB_WindowProc hwnd=0x30206 msg=363 wParam=1 lParam=0
Comment 4 Vitaly Lipatov 2006-06-14 22:13:18 MSD 
trace:edit:EditWndProc_common hwnd=0x8021e msg=e (WM_GETTEXTLENGTH) -- 
0x00000008 
trace:edit:EditWndProc_common hwnd=0x8021e msg=d (WM_GETTEXT) wparam=9 
lparam=7e2e9e30 
GET:swqrsafx 
trace:edit:EditWndProc_common hwnd=0x8021e msg=d (WM_GETTEXT) -- 0x00000008 
trace:edit:EditWndProc_common hwnd=0x8021e msg=e (WM_GETTEXTLENGTH) wparam=0 
lparam=0 
trace:edit:EditWndProc_common hwnd=0x8021e msg=e (WM_GETTEXTLENGTH) -- 
0x00000008 
trace:edit:EditWndProc_common hwnd=0x8021e msg=d (WM_GETTEXT) wparam=9 
lparam=7e2e9e30 
GET:swqrsafx 
trace:edit:EditWndProc_common hwnd=0x8021e msg=d (WM_GETTEXT) -- 0x00000008 
trace:edit:EditWndProc_common hwnd=0x8021e msg=363 (WM_IDLEUPDATECMDUI) 
wparam=1 lparam=0 
trace:edit:EditWndProc_common hwnd=0x8021e msg=363 (WM_IDLEUPDATECMDUI) -- 
0x00000000 
trace:edit:EditWndProc_common hwnd=0x701a6 msg=363 (WM_IDLEUPDATECMDUI) 
wparam=1 lparam=0 
trace:edit:EditWndProc_common hwnd=0x701a6 msg=363 (WM_IDLEUPDATECMDUI) -- 
0x00000000 
trace:edit:EditWndProc_common hwnd=0x8021e msg=e (WM_GETTEXTLENGTH) wparam=0 
lparam=0 
trace:edit:EditWndProc_common hwnd=0x8021e msg=e (WM_GETTEXTLENGTH) -- 
0x00000008 
trace:edit:EditWndProc_common hwnd=0x8021e msg=d (WM_GETTEXT) wparam=9 
lparam=7e2e9e30 
GET:swqrsafx 
trace:edit:EditWndProc_common hwnd=0x8021e msg=d (WM_GETTEXT) -- 0x00000008 
trace:edit:EditWndProc_common hwnd=0x8021e msg=e (WM_GETTEXTLENGTH) wparam=0 
lparam=0 
trace:edit:EditWndProc_common hwnd=0x8021e msg=e (WM_GETTEXTLENGTH) -- 
0x00000008 
trace:edit:EditWndProc_common hwnd=0x8021e msg=d (WM_GETTEXT) wparam=9 
lparam=7e2e9e30
Comment 5 Vitaly Lipatov 2006-06-14 22:23:22 MSD 
trace:edit:EditWndProc_common hwnd=0xa0222 msg=363 (WM_IDLEUPDATECMDUI) 
wparam=1 lparam=0 
trace:edit:EditWndProc_common hwnd=0xa0222 msg=363 (WM_IDLEUPDATECMDUI) -- 
0x00000000 
trace:edit:EditWndProc_common hwnd=0x90220 msg=363 (WM_IDLEUPDATECMDUI) 
wparam=1 lparam=0 
trace:edit:EditWndProc_common hwnd=0x90220 msg=363 (WM_IDLEUPDATECMDUI) -- 
0x00000000 
trace:combo:ComboWndProc_common [0x8019c]: msg WM_IDLEUPDATECMDUI wp 00000001 
lp 00000000 
trace:combo:ComboWndProc_common [0x801ba]: msg WM_GETDLGCODE wp 00000000 lp 
00000000 
trace:combo:ComboWndProc_common [0x801ba]: msg WM_IDLEUPDATECMDUI wp 00000001 
lp 00000000
Comment 6 Анатолий Лютин 2007-02-28 16:06:49 MSK 
Буду смотреть.
Это сообщение отправляется во время ожидания в MFC (idle time) и проверяет - надо ли что-то обновлять или нет.
В вайн это делается слишком часто и отправляется для всех вайнов.Что даёт очень большой поток сообщений.
Это сообщение в вайн нигде не отправляется, соответственно эти сообщения генерит программа (1с), я думаю, что она это делает для то чтобы расставлять приорететы сообщениям через переопределение OnIdle.

Ссылки :
http://www.firststeps.ru/mfc/steps/help/r.php?43
Comment 7 Vitaly Lipatov 2007-04-16 13:03:18 MSD 
Есть такая штука в 1С, как встроенный метод ПриВыборе (или что-то такое) - это когда если ты его определишь, то курсор на клетках Таблиц становится лупой.
Как мы уже выяснили ранее, оно отгребает примерно столько же CPU, сколько наведение курсора на иконку.
НО - если иконки сыпят сообщении только если их окно активно, то Таблицы, судя по всему - всегда.
И - если полос иконок не больше, чем открытых 1С (а это не много), то открытых Таблиц может быть много.
Comment 8 Анатолий Лютин 2007-04-23 21:14:33 MSD 
Средняя загрузка сервера при 5 1с:
wineserver:12-16 % (в холодном режиме)
в 1С при наведении курсора на rebar:19-20 % (при условии, что в холодном режиме 1С берёт 4-5 %)
Comment 9 Анатолий Лютин 2007-04-25 18:07:44 MSD 
Выявлены следующие соотношения:
Посылается большое количество сообщений (в win при наведении на картинку rebar при активном фокусе – 3 WM_TIMER и 2 WM_NCHITTEST ; в linux при тех же условиях – 1 WM_TIMER и разное количество WM_NCHITTEST 2, но обычно 4–5.
Comment 10 Анатолий Лютин 2007-05-05 13:18:38 MSD 
Исключил повторяющиеся последовательности.Загрузка упала ~ на 10%
Comment 11 Vitaly Lipatov 2007-05-11 19:57:10 MSD 
Наверное Константин это давно не получает
Comment 12 Vitaly Lipatov 2007-05-11 19:58:22 MSD 
"если открыть в 1С Таблицу с контекстной чувствительностью (лупа), то на P4-1.8 CPU становится в 14%. Потом можно хоть 10-20 таблиц еще открыть - поднимается до 15-16% - независимо от свернутости/развернутости 1С.

У бухгалтеров же та же операция загоняет Xeon 3.2 в 60..80%.
возможно это из-за того, что они работают в терминалах.
Т.е. обмолот вызовов winapi X-клинто для отсылки удаленному x-серверу стоит значительно больших нервов, чем локальному."
Comment 13 Vitaly Lipatov 2007-05-22 23:12:39 MSD 
Как показали измерения Паши, сообщения при этом крутятся внутри процесса, не доходя до wineserver. Также стало известно, что огромное количество запросов к серверу формируется функциями get_window_children и get_window_tree, которые вызываются до миллиона раз в минуту. Принятно решение их кэшировать.

Как показали наблюдения Коли, такой же поток сообщений существует и в Windows.
Поэтому мы пошли по пути оптимизации обработки.
Comment 14 Михаил Карпухин 2007-06-04 18:50:35 MSD 
попробуйте постоянно двигать мышкой в окне 1с даже пустом загрузка проца 100%
Comment 15 Vitaly Lipatov 2007-06-16 01:54:43 MSD 
Итак, создана кэширующая прослойка обращений к серверу. Это существенно снизило межпроцессное взаимодействие.
Далее на WM_IDLEUPDATECMDUI поставлена задержка, которая вызывает переключение контекста и нормализует загрузку.
Решение не окончательное, требует детализации и измерений.
К релизу готово, нужно тестировать.
Comment 16 Vitaly Lipatov 2008-10-29 08:22:57 MSK 
Для исправления 2726 таймер на процедуру, с id=0, временем 200 сокращён до 500мс.
Comment 17 Александр Морозов 2008-10-29 11:49:17 MSK 
2611, а не 2726