[Mono-dev] Unexpected Delays in P/Invoke
Jason Curl
jcurlnews at arcor.de
Sat Apr 23 15:49:44 UTC 2016
Hello Miguel,
You can see in the code, the last timed element is fclose(f), which is
just closing the file used for diagnostics writing in the timing code,
which when removed, still leaves 6900ms (it varies between 5000ms and >
10000ms).
But I will look at if there is something else I can do based on your hint.
Regards,
Jason.
NSERIAL_EXPORT int WINAPI serial_close(struct serialhandle *handle)
{
clock_t start, end;
FILE *f;
f =
fopen("/home/jcurl/Programming/SerialPortStream/dll/serialunix/build/out.txt",
"a");
fprintf(f, "c: serial_close(handle=%p)\n", handle);
start = clock();
if (handle == NULL) {
errno = EINVAL;
return -1;
}
fprintf(f, "c: serial_close(handle=%p) fd=%d\n", handle, handle->fd);
if (handle->fd == -1) return 0;
flushbuffer(handle);
end = clock();
fprintf(f, "c: serial_close(handle=%p) flushbuffer elapsed=%f\n",
handle,
((double)1000.0*(end-start))/CLOCKS_PER_SEC);
if (handle->prfd != -1) {
close(handle->prfd);
handle->prfd = -1;
}
end = clock();
fprintf(f, "c: serial_close(handle=%p) close(prfd) elapsed=%f\n",
handle,
((double)1000.0*(end-start))/CLOCKS_PER_SEC);
if (handle->pwfd != -1) {
close(handle->pwfd);
handle->pwfd = -1;
}
end = clock();
fprintf(f, "c: serial_close(handle=%p) close(pwfd) elapsed=%f\n",
handle,
((double)1000.0*(end-start))/CLOCKS_PER_SEC);
close(handle->fd);
handle->fd = -1;
end = clock();
fprintf(f, "c: serial_close(handle=%p) close(fd) elapsed=%f\n",
handle,
((double)1000.0*(end-start))/CLOCKS_PER_SEC);
fclose(f);
return 0;
}
On 23/04/2016 17:40, Jason Curl wrote:
> Hello Miguel,
>
> > c: serial_close(handle=0x7fe044008d80) close(fd) elapsed=21,530000
>
> The time is from when the function entered (using the clock()
> function) and the end.
>
> There seems to be about 6900ms between calling the P/Invoke method and
> when the function actually gets called. You'll see a second call later
> works as expected (the C method takes 0,066000ms and the .NET says 0ms
> using).
>
> On 23/04/2016 17:15, Miguel de Icaza wrote:
>> Time the C calls, it is possible that close is flushing the data and
>> is not returning until that happebs
>> On Sat, Apr 23, 2016 at 9:33 AM Jason Curl <jcurlnews at arcor.de> wrote:
>>
>> 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 <http://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
>> <http://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
>> <mailto:Mono-devel-list at lists.ximian.com>
>> > http://lists.ximian.com/mailman/listinfo/mono-devel-list
>> >
>>
>> _______________________________________________
>> Mono-devel-list mailing list
>> Mono-devel-list at lists.ximian.com
>> <mailto:Mono-devel-list at lists.ximian.com>
>> http://lists.ximian.com/mailman/listinfo/mono-devel-list
>>
>
>
>
> _______________________________________________
> Mono-devel-list mailing list
> Mono-devel-list at lists.ximian.com
> http://lists.ximian.com/mailman/listinfo/mono-devel-list
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.ximian.com/pipermail/mono-devel-list/attachments/20160423/b90eeaba/attachment.html>
More information about the Mono-devel-list
mailing list