Re: [jetty-users] Websocket server slow in sending messages under load

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index] [List Home]

Re: [jetty-users] Websocket server slow in sending messages under load

From: Abhirama <abhirama@xxxxxxxxx>
Date: Thu, 21 Jan 2021 21:31:23 +0530
Delivered-to: jetty-users@xxxxxxxxxxx
List-archive: <https://www.eclipse.org/mailman/private/jetty-users/>
List-help: <mailto:jetty-users-request@eclipse.org?subject=help>
List-subscribe: <https://www.eclipse.org/mailman/listinfo/jetty-users>, <mailto:jetty-users-request@eclipse.org?subject=subscribe>
List-unsubscribe: <https://www.eclipse.org/mailman/options/jetty-users>, <mailto:jetty-users-request@eclipse.org?subject=unsubscribe>

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 <sbordet@xxxxxxxxxxx> wrote:

Hi,

On Thu, Jan 21, 2021 at 2:06 PM Abhirama <abhirama@xxxxxxxxx> 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
jetty-users@xxxxxxxxxxx
To unsubscribe from this list, visit https://www.eclipse.org/mailman/listinfo/jetty-users

Follow-Ups:
- Re: [jetty-users] Websocket server slow in sending messages under load
  - From: Simone Bordet
- Re: [jetty-users] Websocket server slow in sending messages under load
  - From: Joakim Erdfelt

References:
- [jetty-users] Websocket server slow in sending messages under load
  - From: Abhirama
- Re: [jetty-users] Websocket server slow in sending messages under load
  - From: Simone Bordet

Prev by Date: Re: [jetty-users] Websocket server slow in sending messages under load
Next by Date: Re: [jetty-users] Websocket server slow in sending messages under load
Previous by thread: Re: [jetty-users] Websocket server slow in sending messages under load
Next by thread: Re: [jetty-users] Websocket server slow in sending messages under load
Index(es):
- Date
- Thread

Breadcrumbs