[Mono-dev] Unexpected Delays in P/Invoke

[Jason Curl]

I've tested the latest snapshot of Mono and the problem remains:

Mono JIT compiler version 4.5.0 (Nightly 4.5.0.421/c5789eb Thu Mar 24 
18:42:59 UTC 2016)
Copyright (C) 2002-2014 Novell, Inc, Xamarin Inc and Contributors. 
www.mono-project.com
     TLS:           __thread
     SIGSEGV:       altstack
     Notifications: epoll
     Architecture:  amd64
     Disabled:      none
     Misc:          softdebug
     LLVM:          supported, not enabled.
     GC:            sgen

nUnit-gui now works properly (4.2.3.4 would hang when trying to close) 
and using MONO debug variables (MONO_LOG_MASK="dll"; 
MONO_LOG_LEVEL="debug", I can see that the method "serial_close" is 
called at the correct time, but I don't see any other activity while 
blocked.

Mono: DllImport searching in: 'nserial' ('libnserial.so').
Mono: Searching for 'serial_close'.
Mono: Probing 'serial_close'.
Mono: Found as 'serial_close'.

PAUSE FOR 6 SECONDS

Mono: DllImport searching in: 'nserial' ('libnserial.so').
Mono: Searching for 'serial_read'.
Mono: Probing 'serial_read'.
Mono: Found as 'serial_read'.
Mono: DllImport searching in: 'nserial' ('libnserial.so').
Mono: Searching for 'serial_terminate'.
Mono: Probing 'serial_terminate'.
Mono: Found as 'serial_terminate'.

Any help is appreciated.

On 22.04.2016 23:37, Jason Curl wrote:
> 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
>
> _______________________________________________
> Mono-devel-list mailing list
> Mono-devel-list at lists.ximian.com
> http://lists.ximian.com/mailman/listinfo/mono-devel-list
>