GNAT.Sockets Streaming inefficiency

GNAT.Sockets Streaming inefficiency

[masterglob]

Configuration: X64, Linux & Windows (GNATPRO 7.4.2)
While using GNAT.Sockets.Stream_Access, there is a real performance issue while using String'Output(...).

My test sends 500 times a 1024-long String using String'Output(TCP_Stream on 127.0.0.1) and the result is:
- Linux : average 'output duration = 3 us
- Windows: average 'output duration = 250 us

From prior discussion with AdaCore, the "String" type is the only one for which this latency is NOT observed on Linux.

Any idea on:
- is there a way to get similar performance on Windows (maybe using another type or method?)
- is there any configuration that may solve this issue?


=============
Result on W7/64
---------
OS=Windows_NT  cygwin
GNAT Pro 7.4.2 (20160527-49)
[SERVER] start...
[SERVER]:bind... 127.0.0.1:4264
[CLIENT] connected...
[SERVER]:connection from 127.0.0.1:56008
[SERVER] Sending 500 messages ...
[CLIENT] waiting for 500 messages ...
[CLIENT]:execution time:  0.000000000
[Server] execution time ( 500msg):  0.140400900 s
[Server] Output_Exec time (1 msg):  0.280801800 ms
[Server] Output_Duration time (1 msg):  0.263417164 ms

=============
Result on Ubuntu/64
---------
OS= 
GNAT Pro 7.4.2 (20160527-49)
[SERVER] start...
[SERVER]:bind... 127.0.0.1:4264
[SERVER]:connection from 127.0.0.1:52574
[CLIENT] connected...
[SERVER] Sending 500 messages ...
[CLIENT] waiting for 500 messages ...
[Server] execution time ( 500msg):  0.001783393 s
[Server] Output_Exec time (1 msg):  0.003072174 ms
[Server] Output_Duration time (1 msg):  0.003204778 ms
[CLIENT]:execution time:  0.001561405

=============
Makefile:
---------
all:build exec
build:
	@gprbuild -p -Ptest_stream_socket_string.gpr
exec: 
	@echo "OS=$$OS  $$OSTYPE"
	@echo $$(gnat --version|head -1)
	@obj/test_stream_socket_string



=============
test_stream_socket_string.gpr:
---------
project Test_Stream_Socket_String is

   for Object_Dir  use "obj";
   for Exec_Dir    use "obj";
   for Main        use ("test_stream_socket_string.adb");
   for Source_Dirs use (".");
   for Languages use ("Ada");

   package Builder is
      for Default_Switches ("Ada") use ("-g","-s","-j0");
   end Builder;

   package Compiler is
      Ada_Opt   := ("-O0");
      Ada_Comp    := ("-gnat12","-g","-gnatU","-gnato","-gnatVa","-fstack-check","-fstack-usage","-gnateE","-gnateF");
      Ada_Style   := ("-gnaty3aAbBCdefhiklL15M120nOprStux");
      Ada_Warning := ("-gnatwah.h.o.st.w");
      for Default_Switches ("Ada") use Ada_Opt & Ada_Comp & Ada_Warning & Ada_Style;
   end Compiler;

   package Binder is
      for Default_Switches ("Ada") use ("-v","-E","-R","-T0");
   end Binder;

   package Linker is
      for Default_Switches ("Ada") use ("-g","-v") ;
   end Linker;

end Test_Stream_Socket_String;



=============
test_stream_socket_string.adb
---------
with Ada.Execution_Time,
     Ada.Real_Time,
     Ada.Text_IO,
     Ada.Exceptions,

     GNAT.Sockets,
     GNAT.Traceback.Symbolic,
     GNAT.OS_Lib;
use GNAT,
    Ada;

use type GNAT.Sockets.Selector_Status,
         Ada.Real_Time.Time,
         Ada.Execution_Time.CPU_Time;

procedure Test_Stream_Socket_String is

   Port    : constant Sockets.Port_Type := 4264;
   Ip_Addr : constant String := "127.0.0.1";

   task type Client_Thread_T is
      entry Start;
      entry Synch;
      entry Wait;
   end Client_Thread_T;
   Client_Thread : Client_Thread_T;
   task type Server_Thread_T is
      entry Start;
      entry Wait;
   end Server_Thread_T;
   Server_Thread : Server_Thread_T;
   
   task body Client_Thread_T is
   
   task body Server_Thread_T is
      Nb_Loop         : constant := 500;
      Cpt             : Integer := Nb_Loop;
      Msg_Size        : constant :=  1024; -- 1 Ko
      Exec_Start_Time : Execution_Time.CPU_Time;
      Exec_Output1    : Execution_Time.CPU_Time;
      Exec_Output2    : Real_Time.Time;
      Output_Exec     : Duration := 0.0;
      Output_Duration : Duration := 0.0;
      Listen          : Sockets.Socket_Type;
      Client          : Sockets.Socket_Type;
      Address         : Sockets.Sock_Addr_Type := (Family => Sockets.Family_Inet,
                                                   Addr   => Sockets.Inet_Addr (Ip_Addr),
                                                   Port   => Port);
      Channel         : Sockets.Stream_Access;
   begin
      accept Start;
      Text_IO.Put_Line ("[SERVER] start...");

      Sockets.Create_Socket (Socket => Listen);
      Text_IO.Put_Line ("[SERVER]:bind... " & Sockets.Image (Address));
      Sockets.Bind_Socket (Socket  => Listen,
                           Address => Address);
      Sockets.Listen_Socket (Listen);

      Sockets.Accept_Socket (Listen, Client, Address);
      Text_IO.Put_Line ("[SERVER]:connection from " & Sockets.Image (Sockets.Get_Peer_Name (Client)));
      Channel := Sockets.Stream (Socket => Client);
      Exec_Start_Time := Execution_Time.Clock;

      Integer'Output (Channel, Cpt);
         Text_IO.Put_Line ("[SERVER] Sending" & Cpt'Img & " messages ...");
      
      while Cpt > 0 loop
         -- Text_IO.Put ('+');
         declare
            S : constant String (1 .. Msg_Size) := (others => '?');
         begin
            Exec_Output1 := Execution_Time.Clock;
            Exec_Output2 := Real_Time.Clock;
            String'Output (Channel, S);
            Output_Exec := Output_Exec + 
              Real_Time.To_Duration (Execution_Time.Clock - Exec_Output1);
            Output_Duration := Output_Duration + 
              Real_Time.To_Duration (Real_Time.Clock - Exec_Output2);
         end;

         Cpt := Cpt - 1;

      end loop;

      Text_IO.Put_Line ("[Server] execution time (" & Nb_Loop'Img & "msg): " &
                          Real_Time.To_Duration (Execution_Time.Clock - Exec_Start_Time)'Img & " s");

      Text_IO.Put_Line ("[Server] Output_Exec time (1 msg): " &
                          Duration'Image (1000.0 * Output_Exec / (Nb_Loop - Cpt)) & " ms");
      Text_IO.Put_Line ("[Server] Output_Duration time (1 msg): " &
                          Duration'Image (1000.0 * Output_Duration / (Nb_Loop - Cpt)) & " ms");

      Sockets.Close_Socket (Socket => Listen);

      accept Wait;
      -- Text_IO.New_Line;
   exception
      when E : others =>
         Text_IO.New_Line;
         Text_IO.Put_Line ("[Server] Exception: " & Exceptions.Exception_Information (E));
         Text_IO.Put_Line (Exceptions.Exception_Message (E));
         Text_IO.Put_Line (Traceback.Symbolic.Symbolic_Traceback (E));
         if Cpt /= Nb_Loop then
            Text_IO.Put_Line ("[Server] Output_Duration time: " &
                                Duration'Image (1000.0 * Output_Duration / (Nb_Loop - Cpt)) & " ms");
         end if;
         GNAT.OS_Lib.OS_Abort;
   end Server_Thread_T;
   
begin
   Server_Thread.Start;
   Client_Thread.Start;
   Client_Thread.Synch;
   Server_Thread.Wait;
   
   Client_Thread.Wait;
   -- Text_IO.New_Line;
exception
   when E : others =>
      Text_IO.Put_Line (Exceptions.Exception_Information (E));
      Text_IO.Put_Line (Exceptions.Exception_Message (E));
      Text_IO.Put_Line (Traceback.Symbolic.Symbolic_Traceback (E));
end Test_Stream_Socket_String;

Re: GNAT.Sockets Streaming inefficiency

[Dmitry A. Kazakov]

On 08/06/2017 12:36, masterglob@gmail.com wrote:
> Configuration: X64, Linux & Windows (GNATPRO 7.4.2)
> While using GNAT.Sockets.Stream_Access, there is a real performance issue while using String'Output(...).
> 
> My test sends 500 times a 1024-long String using String'Output(TCP_Stream on 127.0.0.1) and the result is:
> - Linux : average 'output duration = 3 us
> - Windows: average 'output duration = 250 us
> 
>  From prior discussion with AdaCore, the "String" type is the only one for which this latency is NOT observed on Linux.
> 
> Any idea on:
> - is there a way to get similar performance on Windows (maybe using another type or method?)
> - is there any configuration that may solve this issue?

As a rule you should never use socket stream, especially if you are 
concerned about latencies. Because then you should have used NO_DELAY 
option on the sockets at the both sides. You would send full protocol 
packets (which with NO_DELAY set become frames). Consequently you would 
use Send_Socket once the packet is in the output buffer 
(Stream_Element_Array).

P.S. If you use socket stream then do stream's Write operation.

-- 
Regards,
Dmitry A. Kazakov
http://www.dmitry-kazakov.de

Re: GNAT.Sockets Streaming inefficiency

[Robert Eachus]

On Thursday, June 8, 2017 at 6:36:01 AM UTC-4, maste...@gmail.com wrote:
> Configuration: X64, Linux & Windows (GNATPRO 7.4.2)
> While using GNAT.Sockets.Stream_Access, there is a real performance issue while using String'Output(...).
> 
> My test sends 500 times a 1024-long String using String'Output(TCP_Stream on 127.0.0.1) and the result is:
> - Linux : average 'output duration = 3 us
> - Windows: average 'output duration = 250 us
> 
> From prior discussion with AdaCore, the "String" type is the only one for which this latency is NOT observed on Linux.
> 
> Any idea on:
> - is there a way to get similar performance on Windows (maybe using another type or method?)
> - is there any configuration that may solve this issue?

Have you tried declaring an array of bytes type, and doing an unchecked conversion? Remember that you need the two types to match exactly the descriptive information at the beginning of the objects.

Re: GNAT.Sockets Streaming inefficiency

[gautier_niouzes]

Hello,

It could be related to a performance bottleneck in 'Read and 'Write, perhaps more than to the nature of the stream (socket vs. file vs. ...).

For instance, copying a file with different methods leads to the following timings (here using a byte buffer of sizes 1KB, then 1MB):

xxx'Write / xxx'Read (Stream attributes)......... 0.247916104 seconds
Workarounds with Stream_Element_Array buffer:
  copy (byte buffer from/to SE buffer)........... 0.005628329 seconds
  overlay (read), unchecked_conversion (write)... 0.005184935 seconds
  overlay (read and write)....................... 0.005185743 seconds
Factor (Copy)    44.047905515
Factor (UC)      47.814698544
Factor (Overlay) 47.807248450
Buffer size in bytes..... 1024

xxx'Write / xxx'Read (Stream attributes)......... 0.326904305 seconds
Workarounds with Stream_Element_Array buffer:
  copy (byte buffer from/to SE buffer)........... 0.002427558 seconds
  overlay (read), unchecked_conversion (write)... 0.001585229 seconds
  overlay (read and write)....................... 0.001425978 seconds
Factor (Copy)    134.663849432
Factor (UC)      206.218978456
Factor (Overlay) 229.249192484
Buffer size in bytes..... 1048576

This is with GNAT GPL 2016 / Windows with full "fast mode" switches. There were similar factors when the issue was discoverd in ~2008.
The test procedure is test/test_stream_performance.adb in the Zip-Ada project.
HTH
_________________________ 
Gautier's Ada programming 
http://gautiersblog.blogspot.com/search/label/Ada 
NB: follow the above link for a valid e-mail address 

Re: GNAT.Sockets Streaming inefficiency

[Dmitry A. Kazakov]

On 2017-06-09 15:30, gautier_niouzes@hotmail.com wrote:

> It could be related to a performance bottleneck in 'Read and 'Write,
> perhaps more than to the nature of the stream (socket vs. file vs. ...).

1. Without NODELAY. Writes are buffered and spilled out either when the 
buffer is full or when the coalescing algorithm timeout expired. With 
string length is not a multiply of the buffer and moderate output rate 
or synchronized output, the last frame carrying the string will be 
always delayed. So the observed latency will be more or less the 
coalescing algorithm timeout.

2. With NODELAY. Individual writes are sent in independent frames. If 
'Output or 'Write write individual characters separately, plus the 
string bounds, then the network gets flooded with short frames and the 
latency depends on how good the stack, the OS, the network 
infrastructure are.

In either scenario there is nothing good to expect.

-- 
Regards,
Dmitry A. Kazakov
http://www.dmitry-kazakov.de

Re: GNAT.Sockets Streaming inefficiency

[masterglob]

Le vendredi 9 juin 2017 17:24:24 UTC+2, Dmitry A. Kazakov a écrit :
> On 2017-06-09 15:30, gautier_niouzes@hotmail.com wrote:
> 
> > It could be related to a performance bottleneck in 'Read and 'Write,
> > perhaps more than to the nature of the stream (socket vs. file vs. ...).
> 
> 1. Without NODELAY. Writes are buffered and spilled out either when the 
> buffer is full or when the coalescing algorithm timeout expired. With 
> string length is not a multiply of the buffer and moderate output rate 
> or synchronized output, the last frame carrying the string will be 
> always delayed. So the observed latency will be more or less the 
> coalescing algorithm timeout.
> 
> 2. With NODELAY. Individual writes are sent in independent frames. If 
> 'Output or 'Write write individual characters separately, plus the 
> string bounds, then the network gets flooded with short frames and the 
> latency depends on how good the stack, the OS, the network 
> infrastructure are.
> 
> In either scenario there is nothing good to expect.
> 
> -- 
> Regards,
> Dmitry A. Kazakov
> http://www.dmitry-kazakov.de

I currently do not use "NO_DELAY", but the thing is that the "producer" process is 100%. This tends to indicate that it is not this kind of issue (I would have long execution time, but not a 100% CPU usage).

I have to try other implementations proposed (like using something else than Stream 'write & 'Read)