Smells like you are not waiting for success on the message you sent before sending the next one. This is a classic overqueuing scenario.
Joakim Erdfelt / [email protected] On Thu, Jan 21, 2021 at 10:02 AM Abhirama <[email protected]> wrote: > Thank you so much for the super fast reply! Much appreciated. > > Sorry, I somehow mucked up the copy-paste of the log message! The second > log line was supposed to be: > > Jan 21, 2021 @ > 07:06:56.326 ExtensionStack DEBUG qtp1220759559-6014 Processing > TEXT[len=3953,fin=true,rsv=...,masked=false] > > There were a bunch of other log lines between the two messages I posted > but they were due to other activity (mostly other messages being sent over > several other WS connections). Regarding the idle timeout, wouldn't that > come into play only when there's no traffic on the connection? In my case, > there was always some traffic. So I didn't pay much heed to that. > > Over an extended test run with the server and the client running locally, > I could see a few long GC pauses (I was watching the server through > JVisualVM) of a second or two but nothing huge. I didn't check GC logs, > however. Over the same run, I could see a pattern where the time elapsed > between the RemoteEndpoint::sendString(message, writeCallback) call to the > callback success method being invoked was kind of a sawtooth curve - see > the sample code and the log messages from the run: > > long startTimeNs = System.nanoTime(); > > session.getNativeSession().getRemote().sendString(messageText, new > WriteCallback() { > > @Override > public void writeFailed(Throwable t) { > long endTimeNs = System.nanoTime(); > var durationMs = ((double) (endTimeNs - startTimeNs)) / 1000000.0; > logger.error("Failed to write message to websocket: Took {}ms", > durationMs); > } > > @Override > public void writeSuccess() { > long endTimeNs = System.nanoTime(); > > var durationMs = ((double) (endTimeNs - startTimeNs)) / 1000000.0; > if (durationMs > 100.0) { > logger.warn("TOOK LONGER THAN 100ms: {}ms", durationMs); > } > > logger.debug("Successfully wrote message to the WebSocket channel in > {}ms", durationMs); > } > > }; > > > The durations slowly creep up, then drop and then slow creep up again. The > pattern repeats over and over. That's what I meant by the "sawtooth curve" > above. > > 2021-01-21T15:16:22,896Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 124.149197ms > 2021-01-21T15:16:22,983Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 211.551707ms > 2021-01-21T15:16:23,046Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 274.071959ms > 2021-01-21T15:16:23,159Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 387.987866ms > 2021-01-21T15:16:23,262Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 489.46867ms > 2021-01-21T15:16:23,325Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 552.319841ms > 2021-01-21T15:16:23,389Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 617.347295ms > 2021-01-21T15:16:23,449Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 661.08415ms > 2021-01-21T15:16:23,614Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 826.065565ms > 2021-01-21T15:16:23,723Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 898.192372ms > 2021-01-21T15:16:23,767Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 924.750504ms > 2021-01-21T15:16:23,778Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 930.814351ms > 2021-01-21T15:16:23,786Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 897.71361ms > 2021-01-21T15:16:23,801Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 902.369882ms > 2021-01-21T15:16:23,826Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 937.429601ms > 2021-01-21T15:16:23,879Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 985.381235ms > 2021-01-21T15:16:23,903Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 989.779673ms > 2021-01-21T15:16:23,936Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 993.712366ms > 2021-01-21T15:16:23,970Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1010.190343ms > 2021-01-21T15:16:24,005Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1028.886614ms > 2021-01-21T15:16:24,061Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1073.423766ms > 2021-01-21T15:16:24,099Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1096.688271ms > 2021-01-21T15:16:24,125Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1125.860471ms > 2021-01-21T15:16:24,190Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1178.402526ms > 2021-01-21T15:16:24,294Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1277.004368ms > 2021-01-21T15:16:24,353Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1304.602237ms > 2021-01-21T15:16:24,409Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1327.669391ms > 2021-01-21T15:16:24,436Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1373.754581ms > 2021-01-21T15:16:24,460Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1290.314005ms > 2021-01-21T15:16:24,480Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1311.228668ms > 2021-01-21T15:16:24,499Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1332.770133ms > 2021-01-21T15:16:24,533Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1365.329746ms > 2021-01-21T15:16:24,549Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1357.486048ms > 2021-01-21T15:16:24,557Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1354.207122ms > 2021-01-21T15:16:24,562Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1343.971255ms > 2021-01-21T15:16:24,569Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1328.219353ms > 2021-01-21T15:16:24,578Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1314.677025ms > 2021-01-21T15:16:24,748Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1452.734377ms > 2021-01-21T15:16:24,798Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1487.899628ms > 2021-01-21T15:16:24,805Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1480.240727ms > 2021-01-21T15:16:24,821Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1502.097526ms > 2021-01-21T15:16:24,851Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1518.997969ms > 2021-01-21T15:16:24,857Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1520.080989ms > 2021-01-21T15:16:24,870Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1528.586793ms > 2021-01-21T15:16:24,874Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1533.867999ms > 2021-01-21T15:16:24,940Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1556.994004ms > 2021-01-21T15:16:25,005Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1621.507396ms > 2021-01-21T15:16:25,046Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1636.111375ms > 2021-01-21T15:16:25,052Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1642.690986ms > 2021-01-21T15:16:25,074Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1629.79381ms > 2021-01-21T15:16:25,105Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1604.219814ms > 2021-01-21T15:16:25,154Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1640.512356ms > 2021-01-21T15:16:25,189Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1620.90208ms > 2021-01-21T15:16:25,212Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1641.215848ms > 2021-01-21T15:16:25,224Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1661.761735ms > 2021-01-21T15:16:25,261Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1643.990902ms > 2021-01-21T15:16:25,320Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1298.870224ms > 2021-01-21T15:16:25,324Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1303.671139ms > 2021-01-21T15:16:25,370Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1349.045967ms > 2021-01-21T15:16:25,374Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1281.401043ms > 2021-01-21T15:16:25,379Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1287.297346ms > 2021-01-21T15:16:25,466Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1373.631589ms > 2021-01-21T15:16:25,508Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1405.385726ms > 2021-01-21T15:16:25,520Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1419.37923ms > 2021-01-21T15:16:25,529Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1416.438246ms > 2021-01-21T15:16:25,537Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1370.639405ms > 2021-01-21T15:16:25,547Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1380.414221ms > 2021-01-21T15:16:25,571Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1324.803292ms > 2021-01-21T15:16:25,646Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1400.48142ms > 2021-01-21T15:16:25,777Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1529.227364ms > 2021-01-21T15:16:25,851Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1594.484762ms > 2021-01-21T15:16:25,924Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1678.210598ms > 2021-01-21T15:16:25,997Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1751.634309ms > 2021-01-21T15:16:26,055Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1776.798133ms > 2021-01-21T15:16:26,127Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1796.214049ms > 2021-01-21T15:16:26,157Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1810.261232ms > 2021-01-21T15:16:26,202Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1829.559555ms > 2021-01-21T15:16:26,219Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1833.785878ms > 2021-01-21T15:16:26,245Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1835.310709ms > 2021-01-21T15:16:26,275Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1855.216861ms > 2021-01-21T15:16:26,319Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1895.723651ms > 2021-01-21T15:16:26,424Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1958.782848ms > 2021-01-21T15:16:26,482Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 139.243945ms > 2021-01-21T15:16:26,517Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 173.127246ms > 2021-01-21T15:16:26,553Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 209.365332ms > 2021-01-21T15:16:26,591Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 236.676722ms > 2021-01-21T15:16:26,618Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 274.938896ms > 2021-01-21T15:16:26,641Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 264.056508ms > 2021-01-21T15:16:26,672Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 283.166932ms > 2021-01-21T15:16:26,687Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 216.089737ms > 2021-01-21T15:16:26,706Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 208.838663ms > 2021-01-21T15:16:26,723Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 207.0618ms > 2021-01-21T15:16:26,738Z [WARN ] [container-129] [WebsocketWriter] TOOK > LONGER THAN 100ms: 209.861603ms > 2021-01-21T15:16:28,023Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 102.731079ms > 2021-01-21T15:16:28,165Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 128.315955ms > 2021-01-21T15:16:28,223Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 188.428597ms > 2021-01-21T15:16:28,275Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 238.433164ms > 2021-01-21T15:16:28,316Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 281.506847ms > 2021-01-21T15:16:28,386Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 349.162022ms > 2021-01-21T15:16:28,459Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 421.186862ms > 2021-01-21T15:16:28,534Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 403.581928ms > 2021-01-21T15:16:28,643Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 513.257663ms > 2021-01-21T15:16:28,724Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 592.340569ms > 2021-01-21T15:16:28,796Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 666.4238ms > 2021-01-21T15:16:28,842Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 711.614145ms > 2021-01-21T15:16:28,889Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 758.056856ms > 2021-01-21T15:16:28,970Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 839.283897ms > 2021-01-21T15:16:29,062Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 907.065275ms > 2021-01-21T15:16:29,200Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1026.652641ms > 2021-01-21T15:16:29,293Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1119.837167ms > 2021-01-21T15:16:29,338Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1146.004866ms > 2021-01-21T15:16:29,356Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1169.470446ms > 2021-01-21T15:16:29,384Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1108.835167ms > 2021-01-21T15:16:29,416Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1136.229377ms > 2021-01-21T15:16:29,470Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1171.520838ms > 2021-01-21T15:16:29,529Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1231.670307ms > 2021-01-21T15:16:29,579Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1267.027275ms > 2021-01-21T15:16:29,632Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1312.771066ms > 2021-01-21T15:16:29,676Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1349.952116ms > 2021-01-21T15:16:29,704Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1344.499001ms > 2021-01-21T15:16:29,736Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1371.061208ms > 2021-01-21T15:16:29,781Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1408.427681ms > 2021-01-21T15:16:29,824Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1432.63982ms > 2021-01-21T15:16:29,853Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1426.357621ms > 2021-01-21T15:16:29,885Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1449.377505ms > 2021-01-21T15:16:29,925Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1477.523858ms > 2021-01-21T15:16:30,007Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1557.780603ms > 2021-01-21T15:16:30,051Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1566.918153ms > 2021-01-21T15:16:30,074Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1562.47832ms > 2021-01-21T15:16:30,090Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1575.693332ms > 2021-01-21T15:16:30,110Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1596.213762ms > 2021-01-21T15:16:30,137Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1492.525898ms > 2021-01-21T15:16:30,150Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1506.300113ms > 2021-01-21T15:16:30,157Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1513.640842ms > 2021-01-21T15:16:30,163Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1517.332912ms > 2021-01-21T15:16:30,171Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1450.382792ms > 2021-01-21T15:16:30,178Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1444.455596ms > 2021-01-21T15:16:30,184Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1462.428568ms > 2021-01-21T15:16:30,189Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1468.057318ms > 2021-01-21T15:16:30,196Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1455.884435ms > 2021-01-21T15:16:30,212Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1455.092291ms > 2021-01-21T15:16:30,292Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1523.181656ms > 2021-01-21T15:16:30,400Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1543.341895ms > 2021-01-21T15:16:30,438Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1564.805707ms > 2021-01-21T15:16:30,484Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1604.191056ms > 2021-01-21T15:16:30,513Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1623.993346ms > 2021-01-21T15:16:30,573Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1673.869983ms > 2021-01-21T15:16:30,655Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1733.752034ms > 2021-01-21T15:16:30,743Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1805.451049ms > 2021-01-21T15:16:30,882Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1940.878503ms > 2021-01-21T15:16:30,923Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1964.831965ms > 2021-01-21T15:16:30,965Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1977.9748ms > 2021-01-21T15:16:31,015Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1999.285666ms > 2021-01-21T15:16:31,030Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 2009.594416ms > 2021-01-21T15:16:31,116Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 2039.521642ms > 2021-01-21T15:16:31,158Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 2086.009694ms > 2021-01-21T15:16:31,164Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 2040.223557ms > 2021-01-21T15:16:31,238Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 2128.041292ms > 2021-01-21T15:16:31,265Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 2115.81787ms > 2021-01-21T15:16:31,275Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 2039.64001ms > 2021-01-21T15:16:31,283Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 2047.710574ms > 2021-01-21T15:16:31,297Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1884.327909ms > 2021-01-21T15:16:31,307Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1869.631406ms > 2021-01-21T15:16:31,317Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1762.995618ms > 2021-01-21T15:16:31,325Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1544.616662ms > 2021-01-21T15:16:31,337Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1555.531284ms > 2021-01-21T15:16:31,356Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1573.961146ms > 2021-01-21T15:16:31,381Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1533.147917ms > 2021-01-21T15:16:31,481Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1573.841452ms > 2021-01-21T15:16:31,518Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1578.386559ms > 2021-01-21T15:16:31,560Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1599.836661ms > 2021-01-21T15:16:31,638Z [WARN ] [container-223] [WebsocketWriter] TOOK > LONGER THAN 100ms: 1621.137378ms > 2021-01-21T15:16:33,023Z [WARN ] [container-308] [WebsocketWriter] TOOK > LONGER THAN 100ms: 162.173558ms > 2021-01-21T15:16:33,075Z [WARN ] [container-308] [WebsocketWriter] TOOK > LONGER THAN 100ms: 214.657366ms > 2021-01-21T15:16:33,124Z [WARN ] [container-308] [WebsocketWriter] TOOK > LONGER THAN 100ms: 263.538364ms > > I also have to mention that the BatchMode was set to the default i.e., > AUTO. > > Once I saw the line "Jan 21, 2021 @ > 07:06:56.326 ExtensionStack DEBUG qtp1220759559-6014 Processing > TEXT[len=3953,fin=true,rsv=...,masked=false]", the flush of the websocket > frame was super quick after that. It took <10ms to complete the flush from > that point. Since the flush was quick once Jetty got to the point where it > could flush, I suspected that the client or the network might not be the > bottleneck and that there was something happening where Jetty wasn't able > to get to the point of flushing the frames. Is my logic there incorrect? > > I will try and arrange for a test that is closer to my real environment to > be able to get more information but I can definitely use some ideas on what > I could try to get to the root cause! > > Thank you, > Abhirama. > > On Thu, Jan 21, 2021 at 7:49 PM Simone Bordet <[email protected]> wrote: > >> Hi, >> >> On Thu, Jan 21, 2021 at 2:06 PM Abhirama <[email protected]> wrote: >> > >> > Hi, >> > >> > We're using the Jetty Websocket server (version=9.4.35) in our >> application. We have a scenario where we have about a hundred messages >> (each of size about 2KB to 4KB) to be sent out to a remote client. >> > >> > We're using the async write method RemoteEndpoint.sendString(message, >> new WriteCallback() { ... } ). >> > >> > What we're noticing is a lot of time elapsing between the message >> getting queued and the message being processed and flushed. >> > >> > Here's an example: >> > >> > Jan 21, 2021 @ 06:59:36.981 ExtensionStack DEBUG container-22894 >> Queuing TEXT[len=3953,fin=true,rsv=...,masked=false] >> > ... >> > Jan 21, 2021 @ 07:09:25.841 ExtensionStack DEBUG qtp1220759559-343 >> Processing TEXT[len=6323,fin=true,rsv=...,masked=false] >> > >> > That's almost 7 mins elapsed between the two log lines! >> >> Not sure I understand this? >> The message is not the same (as the second log line shows a larger >> message length). >> >> If there was *no other* log lines between those 2 lines, then it could >> be that the server could not write to the client because the client >> was not reading and the connection went into TCP congestion. >> If that was the case, then I would expect the idle timeout to close >> the connection. By default it is 30 seconds. Did you change it to be >> more than 7 minutes? >> >> Other than that, it could be a long GC pause (did you check the GC logs)? >> >> Lastly, it could be an OS pause, for example due to swapping or THP >> reclamation. >> >> > I've gone through the Jetty code a little bit and suspect it could be >> because of the synchronized block within the ExtensionStack::offerEntry or >> ExtensionStack::pollEntry methods. >> >> Unlikely. >> >> > I must be doing something wrong because sending out a few hundred >> messages on a 2CPU/4GB RAM VM shouldn't be a large load! >> >> Indeed, if the client reads them. Otherwise the server blocks because >> of TCP congestion. >> >> -- >> Simone Bordet >> ---- >> http://cometd.org >> http://webtide.com >> Developer advice, training, services and support >> from the Jetty & CometD experts. >> _______________________________________________ >> jetty-users mailing list >> [email protected] >> To unsubscribe from this list, visit >> https://www.eclipse.org/mailman/listinfo/jetty-users >> > _______________________________________________ > jetty-users mailing list > [email protected] > To unsubscribe from this list, visit > https://www.eclipse.org/mailman/listinfo/jetty-users >
_______________________________________________ jetty-users mailing list [email protected] To unsubscribe from this list, visit https://www.eclipse.org/mailman/listinfo/jetty-users
