[Mono-dev] Unexpected Delays in P/Invoke

[Jason Curl]

I've generally got my library working 
(github.com/jcurl/serialportstream) on Linux with Mono 4.2.3.4 from the 
Xamarin repositories on Ubuntu 16.04, with one small problem.

One new test case (ClosedWhenBlocked) takes 6923ms for a simple close() 
function using marshalling, where the function in C only needs 22ms. 
It's called twice (there's two instances), the second is effectively 
instantaneous. On my machine, the issue is 100% reproducible. My C code 
and .NET is OK (as far as I can tell) and appears to be some blocking 
behaviour in the Marshalling code of the .NET framework. How can I debug 
further if it's me or .NET?

Note, I can't compare on Windows as it's Linux specific code.


Closing serialSource
...
--> serial_close(140601190288768)   => 0x7FE044008D80
...
-->  serial_close(140601190288768) took 6916 ms
IO.Ports.SerialPortStream Verbose: 0 : --> serial_close(140601190288768) 
took 6916 ms
...
Closed serialSource after 6923 ms
...
--> serial_close(140601190278688)  => 0x7FE044006620
-->  serial_close(140601190278688) took 0 ms
-->  serial_close(140601190278688) took 0 ms



The code in question is
         [DllImport("nserial", EntryPoint="serial_close", 
SetLastError=true)]
         private static extern int nserial_close(IntPtr handle);
         public int serial_close(IntPtr handle)
         {
             System.Diagnostics.Stopwatch sw = new 
System.Diagnostics.Stopwatch();
             sw.Start();
             Console.WriteLine("--> serial_close({0})", handle);
             int result = nserial_close(handle);
             Console.WriteLine("-->  serial_close({0}) took {1} ms", 
handle, sw.ElapsedMilliseconds);
             errno = Marshal.GetLastWin32Error();
             Console.WriteLine("-->  serial_close({0}) took {1} ms", 
handle, sw.ElapsedMilliseconds);
             return result;
         }

I added diagnostics to my C code to write performance data to disk and 
it is:
c: serial_close(handle=0x7fe044008d80)
c: serial_close(handle=0x7fe044008d80) fd=4
c: serial_close(handle=0x7fe044008d80) flushbuffer elapsed=0,005000
c: serial_close(handle=0x7fe044008d80) close(prfd) elapsed=0,028000
c: serial_close(handle=0x7fe044008d80) close(pwfd) elapsed=0,046000
c: serial_close(handle=0x7fe044008d80) close(fd) elapsed=21,530000
c: serial_close(handle=0x7fe044006620)
c: serial_close(handle=0x7fe044006620) fd=14
c: serial_close(handle=0x7fe044006620) flushbuffer elapsed=0,004000
c: serial_close(handle=0x7fe044006620) close(prfd) elapsed=0,048000
c: serial_close(handle=0x7fe044006620) close(pwfd) elapsed=0,062000
c: serial_close(handle=0x7fe044006620) close(fd) elapsed=0,066000