date:20160423

Re: [Mono-dev] Unexpected Delays in P/Invoke

2016-04-23 Thread Jason Curl

Hello,

My method for measurement was wrong. I changed to gettimeofday() which 
shows that close(handle->fd) is the culprit and not Mono.

Thankyou for your time and sorry for the noise.
Jason.

On 23.04.2016 17:49, Jason Curl wrote:

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 
> 1ms).

But I will look at if there is something else I can do based on your hint.

Regards,
Jason.

On 23/04/2016 17:40, Jason Curl wrote:

Hello Miguel,

> c: serial_close(handle=0x7fe044008d80) close(fd) elapsed=21,53

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

___
Mono-devel-list mailing list
Mono-devel-list@lists.ximian.com
http://lists.ximian.com/mailman/listinfo/mono-devel-list

Re: [Mono-dev] Unexpected Delays in P/Invoke

2016-04-23 Thread Jason Curl

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 > 
1ms).

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,53

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  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 
 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
> -->

Re: [Mono-dev] Unexpected Delays in P/Invoke

2016-04-23 Thread Jason Curl

Hello Miguel,

> c: serial_close(handle=0x7fe044008d80) close(fd) elapsed=21,53

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 > 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 
 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,53
> 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)

Re: [Mono-dev] Unexpected Delays in P/Invoke

2016-04-23 Thread Miguel de Icaza

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  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
>  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,53
> > 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@lists.ximian.com
> > http://lists.ximian.com/mailman/listinfo/mono-devel-list
> >
>
> ___
> Mono-devel-list mailing list
> Mono-devel-list@lists.ximian.com
> http://lists.ximian.com/mailman/listinfo/mono-devel-list
>
___
Mono-devel-list mailing list
Mono-devel-list@lists.ximian.com
http://lists.ximian.com/mailman/listinfo/mono-devel-list

Re: [Mono-dev] Unexpected Delays in P/Invoke

Re: [Mono-dev] Unexpected Delays in P/Invoke

Re: [Mono-dev] Unexpected Delays in P/Invoke

Re: [Mono-dev] Unexpected Delays in P/Invoke

4 matches

Site Navigation

Mail list logo

Footer information