Opened 4 years ago

Closed 3 years ago

#450 closed улучшение (не воспроизводится)

SSE. Задержка отображения содержимого вкладок

Reported by: san Owned by: alx
Priority: средний Milestone: 1 очередь
Component: sw Keywords:
Cc:

Description

При включенном режиме SSE, при попытке обновить страницу некоторые вкладки не отображаются сразу, приходится долго ждать.
После нажатия Ctrl+F5 появляется "шапка" с вкладками, однако вкладки: Платы, TDM, Генератор, Чат остаются пустыми, на длительное время (40+ секунд). Замечу, что если происходит какое-то событие(авария, сообщение в чате) содержимое вкладок сразу отображается.
r1955
Chrome 84.0.4147.105(64 бит)

Думаю, что будет правильно после обновления сразу отображать содержимое вкладок.

Attachments (2)

1.png (7.6 KB ) - added by san 4 years ago.
2.png (31.3 KB ) - added by san 4 years ago.

Download all attachments as: .zip

Change History (23)

comment:1 by alx, 4 years ago

Можешь приложить сюда дамп обмена по HTTP при загрузке страницы?

comment:2 by san, 4 years ago

Вот дамп.
Браузер 192.168.0.5
SW-01 192.168.1.52

Запись начал перед обновлением страницы. Содержимое вкладки "Платы" отобразилось примерно через минуту, после чего запись закончил.

Last edited 4 years ago by san (previous) (diff)

comment:3 by alx, 4 years ago

Поведение хоста мне кажется очень странным...

17:42:16.745298 IP 192.168.0.5.54685 > 192.168.1.52.80: Flags [P.], seq 4904:5390, ack 175827, win 61441, length 486: HTTP: GET /events HTTP/1.1
17:42:17.214963 IP 192.168.0.5.54721 > 192.168.1.52.80: Flags [P.], seq 7083:7722, ack 34706, win 16092, length 639: HTTP: POST /api.php HTTP/1.1
17:42:17.236822 IP 192.168.1.52.80 > 192.168.0.5.54721: Flags [P.], seq 34706:35664, ack 7722, win 5279, length 958: HTTP: HTTP/1.1 200 OK
17:42:48.387377 IP 192.168.0.5.54721 > 192.168.1.52.80: Flags [P.], seq 7722:8361, ack 35664, win 16425, length 639: HTTP: POST /api.php HTTP/1.1
17:42:48.410524 IP 192.168.1.52.80 > 192.168.0.5.54721: Flags [P.], seq 35664:36622, ack 8361, win 5279, length 958: HTTP: HTTP/1.1 200 OK
17:43:17.156597 IP 192.168.0.5.54721 > 192.168.1.52.80: Flags [P.], seq 8361:8998, ack 36622, win 16185, length 637: HTTP: POST /api.php HTTP/1.1

Первая строчка - запрос от браузера к серверу. В ответ от сервера на порт 54685 - полная тишина, нет даже TCP ACK, что уже странно, учитывая что сервер живой, и мы видим, как по другим соединениям TCP идет обмен... Но что еще более странно, клиентская сторона, отправив данные и не получив в ответ ACK, не делает никаких повторных посылок...

Точно ли приложенный дамп полный? Какие фильтры использовались? Не было ли в процессе обмена каких-нибудь сообщений ICMP, которые не попали в дамп? Где (на клиенте, на сервере, между ними) был сделан этот дамп?

comment:4 by alx, 4 years ago

Приходят в голову мысли о каких-то конфликтах адресов...

Попробуй воспроизвести проблему на "Нижнем самурае" (192.168.0.60 или [2a03:1ac0:2e92:d910:ad:c2ff:fe00:e1]).

comment:5 by alx, 4 years ago

Вот как должно быть:

16:07:50.787019 IP6 (flowlabel 0x9357c, hlim 64, next-header TCP (6) payload length: 559) 2a02:2698:22:24bd::b851.48186 > 2a03:1ac0:2e92:d910:ad:c2ff:fe00:e1.80: Flags [P.], cksum 0x3ef5 (incorrect -> 0x0f72), seq 2134:2661, ack 1080, win 501, options [nop,nop,TS val 1853634997 ecr 278025409], length 527: HTTP, length: 527
	GET /events HTTP/1.1
	Host: [2a03:1ac0:2e92:d910:ad:c2ff:fe00:e1]
	Connection: keep-alive
	Accept: text/event-stream
	Cache-Control: no-cache
	User-Agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/84.0.4147.105 Safari/537.36
	Referer: http://[2a03:1ac0:2e92:d910:ad:c2ff:fe00:e1]/
	Accept-Encoding: gzip, deflate
	Accept-Language: ru-RU,ru;q=0.9,en-US;q=0.8,en;q=0.7
	Cookie: login=admin; time=1596884863; password=****************; nonce=2459fffeb95d8957427718a3cc811dfc
	
16:07:50.828566 IP6 (class 0x04, hlim 61, next-header TCP (6) payload length: 32) 2a03:1ac0:2e92:d910:ad:c2ff:fe00:e1.80 > 2a02:2698:22:24bd::b851.48186: Flags [.], cksum 0xf66f (correct), ack 2661, win 3036, options [nop,nop,TS val 278025869 ecr 1853634997], length 0
16:07:51.006138 IP6 (class 0x04, hlim 61, next-header TCP (6) payload length: 268) 2a03:1ac0:2e92:d910:ad:c2ff:fe00:e1.80 > 2a02:2698:22:24bd::b851.48186: Flags [P.], cksum 0x3c96 (correct), seq 1080:1316, ack 2661, win 3036, options [nop,nop,TS val 278026045 ecr 1853634997], length 236: HTTP, length: 236
	HTTP/1.1 200 OK
	Transfer-Encoding: chunked
	Connection: keep-alive
	Cache-Control: no-cache
	Content-Type: text/event-stream; charset=utf-8
	Date: Sat, 08 Aug 2020 11:07:50 GMT
	
	31
	retry: 5000
	data: {"type":"resync"}
	id: 1104601
	
	
16:07:51.006224 IP6 (flowlabel 0x9357c, hlim 64, next-header TCP (6) payload length: 32) 2a02:2698:22:24bd::b851.48186 > 2a03:1ac0:2e92:d910:ad:c2ff:fe00:e1.80: Flags [.], cksum 0x3ce6 (incorrect -> 0xfddf), ack 1316, win 501, options [nop,nop,TS val 1853635216 ecr 278026045], length 0

Получив событие типа "resync" браузер запрашивает текущее состояние блока - список плат, список аварий и т.п. В твоем эксперименте этого события почему-то не приходит, поэтому и список плат не запрашивается.

in reply to:  3 comment:6 by alx, 4 years ago

Replying to alx:

Где (на клиенте, на сервере, между ними) был сделан этот дамп?

Судя по некорректным контрольным суммам IP в запросах, дамп был сделан на стороне клиента. Было бы интересно посмотреть, что видно на стороне сервера. А еще лучше - одновременно и там, и там...

comment:7 by san, 4 years ago

Точно ли приложенный дамп полный?

Точно не полный, какие фильтры я не вспомню уже, но вот нефильтрованный дамп.

Попробуй воспроизвести проблему на "Нижнем самурае"

Визуально воспроизводится аналогично.

in reply to:  7 comment:8 by alx, 4 years ago

Replying to san:

Точно не полный, какие фильтры я не вспомню уже, но вот нефильтрованный дамп.

Вот, совсем другое дело. Видно, что ответ браузер получил. Следовательно, проблема на его стороне.

А в консоли браузера ошибок нет?

comment:9 by alx, 4 years ago

Попробуй сейчас открыть "Нижний самурай". Я заметил, что события сервера парсились функцией parseJSON(), тогда как во всех остальных местах использовалась собственная обертка evalJSON(). Заменил первую на вторую чтобы было "как везде". Хотя скорее всего никакой разницы не будет, так как обе функции - обертки нативной функции JSON.parse()... Мой Хром работает одинаково с обоими вариантами, но вдруг твоему что-то не понравилось...

Last edited 4 years ago by alx (previous) (diff)

comment:10 by san, 4 years ago

Открыл Самурай, разницы не заметил, ошибок в консоли нет.

comment:11 by alx, 4 years ago

Подобавлял вывод контрольных точек в консоль. Обнови, пожалуйста, страничку в "Нижнем самурае" и скажи, что напишет в консоль.

by san, 4 years ago

Attachment: 1.png added

by san, 4 years ago

Attachment: 2.png added

comment:12 by san, 4 years ago

Все 4 надписи появились только спустя длительное время, во время отображения содержимого вкладки

comment:13 by alx, 4 years ago

Я здаюсь. Все контрольный точки пройдены. "checkpoint 4" - самая последняя. В следующей за ней строке отправляется запрос "board", которого твой браузер, судя по дампу, почему-то не отправляет... Необъяснимо...

comment:14 by san, 4 years ago

Так они пройдены только ПОСЛЕ длительного ожидания...

comment:15 by san, 4 years ago

Ещё заметил, что при установке в консоли уровня вывода "Verbose", после обновления страницы постепенно накапливаются какие-то сообщения:

in reply to:  12 comment:16 by alx, 4 years ago

Replying to san:

Все 4 надписи появились только спустя длительное время, во время отображения содержимого вкладки

А-а-а... Сообщение "checkpoint 1" выводится немедленно после получения любого сообщения. Как мы видим по дампу, сообщение {"type":"resync"} передается немедленно после подключения браузера, и браузер его принимает. Но обработчик события вызывает, как ты пишешь, спустя длительное время. Следовательно, проблема сидит где-то внутри барузера. Странно только, что тот же самый браузер у меня работает нормально... Возможно, проблема связана не с кодом самого (или не только с кодом самого) браузера, а какой-то используемой библиотекой, которая в наших системах отличается...

Что с этим делать - непонятно... Путь пока тикет повисит, вдруг появятся какие-нибудь идеи...

comment:17 by alx, 4 years ago

Я только что заметил, что браузер начинает обрабатывать сообщение после того как через минуту бездействия сервер передает в соединение пустой комментарий ":\n" (keep-alive для предотвращения разъединения). Возникла мысль попробовать передавать это сразу после первого сообщения.

Попробуй еще раз открыть "Нижний самурай".

comment:18 by san, 4 years ago

Также, пустая вкладка висит минуту...

Ещё браузер "просыпается" и отображает содержимое вкладки если происходит какой-нибудь ивент, например авария.

comment:19 by alx, 4 years ago

В порядке шаманства: вычитал где-то о том, что надо послать в самом начале 2 килобайта мусора (закомментаренного), почему-то было написано, что это надо для IE (вообще-то IE не поддерживает SSE). Сделал это в "Нижнем самурае". Попробуй, не будет ли каких-либо улучшений?

И правильно ли я понимаю, что после запроса и отрисовки списка плат задержек с реакцией на события уже не наблюдается?

comment:20 by san, 4 years ago

Попробовал, улучшение не вижу.
Да, никаких задержек событий не наблюдается, проблема только с задержкой первого вывода содержимого вкладки.

Version 0, edited 4 years ago by san (next)

comment:21 by san, 3 years ago

Resolution: не воспроизводится
Status: newclosed

В r1975 ничего похожего не замечаю.
После нажатия Ctrl+F5 сразу отображается всё содержимое.
Chrome 86.0.4240.193(64 бит)

Толи в хроме пофиксили что-то, толи у нас что-то изменилось.
Вообщем сейчас всё хорошо.

Note: See TracTickets for help on using tickets.