From owner-freebsd-net@freebsd.org Thu Jan 7 17:03:32 2016 Return-Path: Delivered-To: freebsd-net@mailman.ysv.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:1900:2254:206a::19:1]) by mailman.ysv.freebsd.org (Postfix) with ESMTP id AA56CA66BBD for ; Thu, 7 Jan 2016 17:03:32 +0000 (UTC) (envelope-from vivek@mailermailer.com) Received: from mail-qg0-x22b.google.com (mail-qg0-x22b.google.com [IPv6:2607:f8b0:400d:c04::22b]) (using TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)) (Client CN "smtp.gmail.com", Issuer "Google Internet Authority G2" (verified OK)) by mx1.freebsd.org (Postfix) with ESMTPS id 7D04E18DA for ; Thu, 7 Jan 2016 17:03:32 +0000 (UTC) (envelope-from vivek@mailermailer.com) Received: by mail-qg0-x22b.google.com with SMTP id o11so332166144qge.2 for ; Thu, 07 Jan 2016 09:03:32 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=mailermailer.com; s=google; h=from:content-type:subject:message-id:date:to:mime-version; bh=pIoSHVlEyT1afRFlxtRlRNSfvl6JCB/Pc9Nnhxq4le0=; b=Nd7w3A6XePVzEEToZI5sWn8NsSVF+tDVrXhjXfUWmXR5288R7FuXMcYl8O/u3gV9w3 gO/LQnzSX12uKkIcfxX4ZWN53suD78mKjp2L5u7YY1tdnyDBODN7nglfHLgv45QX/xoP cDIUcMnBYbJaGXbiUad78ROhjIIW0H72RXQtI= X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20130820; h=x-gm-message-state:from:content-type:subject:message-id:date:to :mime-version; bh=pIoSHVlEyT1afRFlxtRlRNSfvl6JCB/Pc9Nnhxq4le0=; b=B3lUQF5l6vKuwiyQ6CrqjQeMbGH+cdHG6DtFiIKFcM3a2pfeNxsuEruValIGKyViBS xJ4xxTTiWDZChCZqQCEJzA6GlZZwb0a1IoR20fh8LkzsEVvLP+h/egejYPia9dutXGtm DlOMT2bHffAHSIRZ/tbHAgl0kJ/+BqMftK/C/RNwbG+s3jtuTYKucgS+W+ayaY3G9W4J O1L4Bpvg9+HVuzFNbVDSnLM7lmuakxYhtxDo1Q891aBO66GQA9E1jggMK5c1ZmyfPXYe YpjWD5ZvkNgQ6fv1116oN+Hr07U8iY1GhvpLEb0VgSMtckoEwDXmgLrx4j4wk77w16kX drDg== X-Gm-Message-State: ALoCoQmpELzP8GoPiIy3gK4JtxobyzmoNQ0zuF3FIQrxoyQxiKh+HC94gOwPsU8rDE4Nk3aNoukQ9CALz0Zgmgtaomg1Qx2Qgw== X-Received: by 10.140.134.198 with SMTP id 189mr148916487qhg.58.1452186211434; Thu, 07 Jan 2016 09:03:31 -0800 (PST) Received: from vick.int.kcilink.com (74-92-149-60.static.comcast.kcilink.com. [74.92.149.60]) by smtp.gmail.com with ESMTPSA id b135sm3536491qka.2.2016.01.07.09.03.30 for (version=TLS1 cipher=ECDHE-RSA-AES128-SHA bits=128/128); Thu, 07 Jan 2016 09:03:30 -0800 (PST) From: Vick Khera Content-Type: multipart/mixed; boundary="Apple-Mail=_28465A14-1206-49C8-A6B8-CE07E76BCD1C" Subject: 250x slowdown on localhost sockets with certain sized write(2) call from perl Message-Id: <2392D9E1-CA83-42F2-A3C9-DFF63772539F@mailermailer.com> Date: Thu, 7 Jan 2016 12:03:29 -0500 To: freebsd-net@freebsd.org Mime-Version: 1.0 (Mac OS X Mail 9.2 \(3112\)) X-Mailer: Apple Mail (2.3112) X-Content-Filtered-By: Mailman/MimeDel 2.1.20 X-BeenThere: freebsd-net@freebsd.org X-Mailman-Version: 2.1.20 Precedence: list List-Id: Networking and TCP/IP with FreeBSD List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Thu, 07 Jan 2016 17:03:32 -0000 --Apple-Mail=_28465A14-1206-49C8-A6B8-CE07E76BCD1C Content-Transfer-Encoding: quoted-printable Content-Type: text/plain; charset=utf-8 I noticed a very curious slowdown in submitting email via a perl program = to a mail server running on the same host. I narrowed it down to = messages which were exactly 16332 bytes or shorted. Once they hit 16333 = bytes, they submit extremely fast. This slowdown only affects = connections on the local host. Connections to a remote mail server are = unaffected. I=E2=80=99m not 100% sure if this is a bug in FreeBSD or in Perl=E2=80=99s= Net::SMTP module, but the smallest test case I could come up with is = below. My hunch is that it is FreeBSD=E2=80=99s bug because I cannot = reproduce this problem on several linux versions. How to reproduce it: In window A, run "smtp-sink -c -4 :8025 10" with the smtp-sink program = from Postfix. Alternatively, run the "perl-sink" program below, which = requires the p5-Net-SMTP-Server package. You really don=E2=80=99t want = to point the test program at a real mail server, though it does the same = slowdown with postfix when sending a hand-crafted message of the right = size. In window B, run "perl standalone-smtp-speed.pl". On my FreeBSD 9.3 and = 10.2 systems, this output looks consistently like this: length=3D16327 elapsed =3D 0.106297 **SLOW length=3D16328 elapsed =3D 0.108077 **SLOW length=3D16329 elapsed =3D 0.101655 **SLOW length=3D16330 elapsed =3D 0.106082 **SLOW length=3D16331 elapsed =3D 0.10716 **SLOW length=3D16332 elapsed =3D 0.106499 **SLOW length=3D16333 elapsed =3D 0.00041 length=3D16334 elapsed =3D 0.00041 length=3D16335 elapsed =3D 0.000415 length=3D16336 elapsed =3D 0.000367 That is, up until the time the length of the message hits 16333 bytes, = it is about 250 times slower to send the message to the mail server. It = does not matter how many before or after messages are sent or what their = lengths are, it is always that length threshold that causes a material = shift in the time it takes. Perl=E2=80=99s SMTP send ultimately ends up calling syswrite() from = perl, which is write(2) from C. This is where the slowness comes, it = seems. The syswrite() always completes with one call =E2=80=94 no = retries are necessary for short writes. If you update the standalone-smtp-speed.pl script to point to the sink = program on a different host, all the lengths run fast. I tried to make a test case that just uses syswrite() directly without = the SMTP module, but I couldn=E2=80=99t do it. Maybe it requires some = data to be received too. I don=E2=80=99t know. Any ideas as to why? The only clue I found was this kernel PR = referencing the number 16332 as the length of partial writes to a = socket. https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=3D173309 --Apple-Mail=_28465A14-1206-49C8-A6B8-CE07E76BCD1C Content-Disposition: attachment; filename=perl-sink Content-Type: application/octet-stream; name="perl-sink" Content-Transfer-Encoding: 7bit #!/usr/local/bin/perl use strict; use Net::SMTP::Server; use Net::SMTP::Server::Client; $|=1; my $s = new Net::SMTP::Server('vk-dev',8025); while (my $conn = $s->accept()) { my $client = new Net::SMTP::Server::Client($conn) || die("Unable to handle client connection: $!\n"); $client->process(); print "."; } --Apple-Mail=_28465A14-1206-49C8-A6B8-CE07E76BCD1C--