Re: [4/4] ntdll: Properly set flag which indicates buffer empty state.

[Alexandre Julliard]

Dmitry Timoshkov  writes:
> dlls/kernel32/tests/comm.c |  5 +----
>  dlls/ntdll/serial.c        | 13 +++++--------
>  2 files changed, 6 insertions(+), 12 deletions(-)

It doesn't work here:

../../../tools/runtest -q -P wine -M kernel32.dll -T ../../.. -p kernel32_test.exe.so comm.c && touch comm.ok
comm.c:835: Test failed: WriteFile took 1 ms to write 17 Bytes at 150 Baud
comm.c:848: Test failed: WaitCommEvent failed with a timeout
comm.c:859: Test failed: WaitCommEvent error 997
comm.c:860: Test failed: WaitCommEvent: expected EV_TXEMPTY, got 0
comm.c:865: Test failed: WaitCommEvent used 1000 ms for waiting
comm.c:1895: Tests skipped: interactive tests (set WINETEST_INTERACTIVE=1)
make: *** [comm.ok] Error 5

[4/4] ntdll: Properly set flag which indicates buffer empty state.

[Wolfgang Walter]

On Tuesday 27 August 2013 21:14:05 Alexandre Julliard wrote:
> Dmitry Timoshkov  writes:
> > dlls/kernel32/tests/comm.c |  5 +----
> >  dlls/ntdll/serial.c        | 13 +++++--------
> >  2 files changed, 6 insertions(+), 12 deletions(-)
>
> It doesn't work here:
>
> ../../../tools/runtest -q -P wine -M kernel32.dll -T ../../.. -p
> kernel32_test.exe.so comm.c && touch comm.ok comm.c:835: Test failed:
> WriteFile took 1 ms to write 17 Bytes at 150 Baud comm.c:848: Test failed:
> WaitCommEvent failed with a timeout
> comm.c:859: Test failed: WaitCommEvent error 997
> comm.c:860: Test failed: WaitCommEvent: expected EV_TXEMPTY, got 0
> comm.c:865: Test failed: WaitCommEvent used 1000 ms for waiting
> comm.c:1895: Tests skipped: interactive tests (set WINETEST_INTERACTIVE=1)
> make: *** [comm.ok] Error 5

I think TIMEOUT (1s) in kernel32/tests/comm.c is too short and the test for < 
900, too.

Here it tooks often 1100 milliseconds and more (with vanilla 1.6). And I 
checked the actual git-tree: the test fails here, too (but not always).

Regards,

[4/4] ntdll: Properly set flag which indicates buffer empty state.

[Dmitry Timoshkov]

Alexandre Julliard  wrote:
> It doesn't work here:
>
> ../../../tools/runtest -q -P wine -M kernel32.dll -T ../../.. -p kernel32_test.exe.so comm.c && touch comm.ok
> comm.c:835: Test failed: WriteFile took 1 ms to write 17 Bytes at 150 Baud
> comm.c:848: Test failed: WaitCommEvent failed with a timeout
> comm.c:859: Test failed: WaitCommEvent error 997
> comm.c:860: Test failed: WaitCommEvent: expected EV_TXEMPTY, got 0
> comm.c:865: Test failed: WaitCommEvent used 1000 ms for waiting
> comm.c:1895: Tests skipped: interactive tests (set WINETEST_INTERACTIVE=1)
> make: *** [comm.ok] Error 5

I assume it's a real hardware and not a VM? Is this with a real COM port,
or USB-serial cable? If the latter one what driver is it using?

[4/4] ntdll: Properly set flag which indicates buffer empty state.

[Dmitry Timoshkov]

Dmitry Timoshkov  wrote:
> Alexandre Julliard  wrote:
> > It doesn't work here:
> >
> > ../../../tools/runtest -q -P wine -M kernel32.dll -T ../../.. -p kernel32_test.exe.so comm.c && touch comm.ok
> > comm.c:835: Test failed: WriteFile took 1 ms to write 17 Bytes at 150 Baud
> > comm.c:848: Test failed: WaitCommEvent failed with a timeout
> > comm.c:859: Test failed: WaitCommEvent error 997
> > comm.c:860: Test failed: WaitCommEvent: expected EV_TXEMPTY, got 0
> > comm.c:865: Test failed: WaitCommEvent used 1000 ms for waiting
> > comm.c:1895: Tests skipped: interactive tests (set WINETEST_INTERACTIVE=1)
> > make: *** [comm.ok] Error 5
>
> I assume it's a real hardware and not a VM? Is this with a real COM port,
> or USB-serial cable? If the latter one what driver is it using?

Looking at the failure messages above once again, I can say that WriteFile
failure is definitely not caused by this patch. Does running the test several
times cause the same failures? In any case it would be interesting to see
the +comm log with "ntdll: Add a trace for transmitter's buffer empty flag."
applied.

And current logic of setting the empty buffer flag is really broken, it
always sets the flag to a not zero value if ioctl(TIOCOUTQ) succeeds.

[4/4] ntdll: Properly set flag which indicates buffer empty state.

[Alexandre Julliard]

Dmitry Timoshkov  writes:
> Dmitry Timoshkov  wrote:
> > Alexandre Julliard  wrote:
> > > It doesn't work here:
> > >
> > > ../../../tools/runtest -q -P wine -M kernel32.dll -T ../../.. -p kernel32_test.exe.so comm.c && touch comm.ok
> > > comm.c:835: Test failed: WriteFile took 1 ms to write 17 Bytes at 150 Baud
> > > comm.c:848: Test failed: WaitCommEvent failed with a timeout
> > > comm.c:859: Test failed: WaitCommEvent error 997
> > > comm.c:860: Test failed: WaitCommEvent: expected EV_TXEMPTY, got 0
> > > comm.c:865: Test failed: WaitCommEvent used 1000 ms for waiting
> > > comm.c:1895: Tests skipped: interactive tests (set WINETEST_INTERACTIVE=1)
> > > make: *** [comm.ok] Error 5
> >
> > I assume it's a real hardware and not a VM? Is this with a real COM port,
> > or USB-serial cable? If the latter one what driver is it using?
>
> Looking at the failure messages above once again, I can say that WriteFile
> failure is definitely not caused by this patch. Does running the test several
> times cause the same failures? In any case it would be interesting to see
> the +comm log with "ntdll: Add a trace for transmitter's buffer empty flag."
> applied.

The WriteFile error is a timing thing, it doesn't always happen (and
that test is clearly broken, ticks can be incremented at any point).
The other errors always happen. It's a real COM port.

[4/4] ntdll: Properly set flag which indicates buffer empty state.

[Dmitry Timoshkov]

Alexandre Julliard  wrote:
> > > I assume it's a real hardware and not a VM? Is this with a real COM port,
> > > or USB-serial cable? If the latter one what driver is it using?
> >
> > Looking at the failure messages above once again, I can say that WriteFile
> > failure is definitely not caused by this patch. Does running the test several
> > times cause the same failures? In any case it would be interesting to see
> > the +comm log with "ntdll: Add a trace for transmitter's buffer empty flag."
> > applied.
>
> The WriteFile error is a timing thing, it doesn't always happen (and
> that test is clearly broken, ticks can be incremented at any point).
> The other errors always happen. It's a real COM port.

Could you please generate a log with additional trace for the empty flag?

[4/4] ntdll: Properly set flag which indicates buffer empty state.

[Wolfgang Walter]

On Wednesday 28 August 2013 12:41:00 Dmitry Timoshkov wrote:
> Dmitry Timoshkov  wrote:
> > Alexandre Julliard  wrote:
> > > It doesn't work here:
> > >
> > > ../../../tools/runtest -q -P wine -M kernel32.dll -T ../../.. -p
> > > kernel32_test.exe.so comm.c && touch comm.ok comm.c:835: Test failed:
> > > WriteFile took 1 ms to write 17 Bytes at 150 Baud comm.c:848: Test
> > > failed: WaitCommEvent failed with a timeout
> > > comm.c:859: Test failed: WaitCommEvent error 997
> > > comm.c:860: Test failed: WaitCommEvent: expected EV_TXEMPTY, got 0
> > > comm.c:865: Test failed: WaitCommEvent used 1000 ms for waiting
> > > comm.c:1895: Tests skipped: interactive tests (set
> > > WINETEST_INTERACTIVE=1)
> > > make: *** [comm.ok] Error 5
> >
> > I assume it's a real hardware and not a VM? Is this with a real COM port,
> > or USB-serial cable? If the latter one what driver is it using?
>
> Looking at the failure messages above once again, I can say that WriteFile
> failure is definitely not caused by this patch. Does running the test
> several times cause the same failures? In any case it would be interesting
> to see the +comm log with "ntdll: Add a trace for transmitter's buffer
> empty flag." applied.
>
> And current logic of setting the empty buffer flag is really broken, it
> always sets the flag to a not zero value if ioctl(TIOCOUTQ) succeeds.

Yes, but this should be no problem for the test.

If you only have TIOCOUTQ it is very difficult to do otherwise. You would have 
to monitor any write to the serial port by any thread.

The applications I know write something and then wait, so the imperfect 
emulation we have now is enough.

Regards,

[4/4] ntdll: Properly set flag which indicates buffer empty state.

[Wolfgang Walter]

Hello Dimitry,

I think I now found the difference between my patches and yours and what makes 
that one application fail (with or without [4/4] ntdll: Properly set flag 
which indicates buffer empty state.)

My patch removes the attempt to flag EV_TXEMPTY only once.

In check_events() EV_TXEMPTY is set:

if (mask & EV_TXEMPTY)
    {
        if (!old->temt && new->temt)
            ret |= EV_TXEMPTY;
    }

I think that happens:

* application writes data to com port.
* all is written, serial buffer is empty
* application calls  WaitCommEvent()
* wait_on() is called
* wait_on() calls get_irq_info()
* get_irq_info() sets commio->irq_info->temt = 1
* wait_on() calls check_events() and uses sets commio->irq_info for old an new
* so old->temt == new->temt and EV_TXEMPTY is not set
* if there are no other events (in real world basically EV_RXCHAR):
* wait_for_event() is startet with commio->irq_info->temt set to one
* wait_for_event() calls get_irq_info() with new_irq_info()
* get_irq_info() sets new_irq_info->temt = 1 because the buffer is still empty
* wait_for_event() calls check_events() with new_irq_info and commio->irq_info
* again check_events() will not set EV_TXEMPTY as both have temt == 1

It seems that we do not recover from that hang.

Please correct me if I misread the code and I'm wrong.

I think it's better if WaitCommEvent() returns with EV_TXEMPTY even if there 
has no new data been sent in between:

* if an application waits only for EV_TXEMPTY then there is no problem.
* if it waits for i.e. EV_TXEMPTY|EV_RXEMPTY it may busy loops. Still better 
then not waiting forever.

Sending EV_TXEMPTY only once after the write buffer got empty is not easy to 
implement I think. One way would be: block a write until it finished and 
buffer is empty, the set a flag.

Am Mittwoch, 28. August 2013, 12:41:00 schrieb Dmitry Timoshkov:
> Dmitry Timoshkov  wrote:
> > Alexandre Julliard  wrote:
> > > It doesn't work here:
> > >
> > > ../../../tools/runtest -q -P wine -M kernel32.dll -T ../../.. -p
> > > kernel32_test.exe.so comm.c && touch comm.ok comm.c:835: Test failed:
> > > WriteFile took 1 ms to write 17 Bytes at 150 Baud comm.c:848: Test
> > > failed: WaitCommEvent failed with a timeout
> > > comm.c:859: Test failed: WaitCommEvent error 997
> > > comm.c:860: Test failed: WaitCommEvent: expected EV_TXEMPTY, got 0
> > > comm.c:865: Test failed: WaitCommEvent used 1000 ms for waiting
> > > comm.c:1895: Tests skipped: interactive tests (set
> > > WINETEST_INTERACTIVE=1)
> > > make: *** [comm.ok] Error 5
> >
> > I assume it's a real hardware and not a VM? Is this with a real COM port,
> > or USB-serial cable? If the latter one what driver is it using?
>
> Looking at the failure messages above once again, I can say that WriteFile
> failure is definitely not caused by this patch. Does running the test
> several times cause the same failures? In any case it would be interesting
> to see the +comm log with "ntdll: Add a trace for transmitter's buffer
> empty flag." applied.
>
> And current logic of setting the empty buffer flag is really broken, it
> always sets the flag to a not zero value if ioctl(TIOCOUTQ) succeeds.

Regards,

[4/4] ntdll: Properly set flag which indicates buffer empty state.

[Dmitry Timoshkov]

Wolfgang Walter  wrote:
> I think that happens:
> - application writes data to com port.
> - all is written, serial buffer is empty
> - application calls  WaitCommEvent()
> - wait_on() is called
> - wait_on() calls get_irq_info()
> - get_irq_info() sets commio->irq_info->temt = 1
> - wait_on() calls check_events() and uses sets commio->irq_info for old an new
> - so old->temt == new->temt and EV_TXEMPTY is not set
> - if there are no other events (in real world basically EV_RXCHAR):
> - wait_for_event() is startet with commio->irq_info->temt set to one
> - wait_for_event() calls get_irq_info() with new_irq_info()
> - get_irq_info() sets new_irq_info->temt = 1 because the buffer is still empty
> - wait_for_event() calls check_events() with new_irq_info and commio->irq_info
> - again check_events() will not set EV_TXEMPTY as both have temt == 1
>
> It seems that we do not recover from that hang.
>
> Please correct me if I misread the code and I'm wrong.
>
> I think it's better if WaitCommEvent() returns with EV_TXEMPTY even if there 
> has no new data been sent in between:

That means that WaitCommEvent(EV_TXEMPTY) without any prior WriteFile
would always return success and signal the EV_TXEMPTY event. My tests
show that WaitCommEvent(EV_TXEMPTY) fails with a timeout in this case.
Since the serial device is very slow it should be unlikely that after
successful WriteFile() with some data WaitCommEvent() sees an already
empty transmitter's output queue.

[4/4] ntdll: Properly set flag which indicates buffer empty state.

[Dmitry Timoshkov]

Dmitry Timoshkov  wrote:
> Wolfgang Walter  wrote:
> > I think that happens:
> > - application writes data to com port.
> > - all is written, serial buffer is empty
> > - application calls  WaitCommEvent()
> > - wait_on() is called
> > - wait_on() calls get_irq_info()
> > - get_irq_info() sets commio->irq_info->temt = 1
> > - wait_on() calls check_events() and uses sets commio->irq_info for old an new
> > - so old->temt == new->temt and EV_TXEMPTY is not set
> > - if there are no other events (in real world basically EV_RXCHAR):
> > - wait_for_event() is startet with commio->irq_info->temt set to one
> > - wait_for_event() calls get_irq_info() with new_irq_info()
> > - get_irq_info() sets new_irq_info->temt = 1 because the buffer is still empty
> > - wait_for_event() calls check_events() with new_irq_info and commio->irq_info
> > - again check_events() will not set EV_TXEMPTY as both have temt == 1
> >
> > It seems that we do not recover from that hang.
> >
> > Please correct me if I misread the code and I'm wrong.
> >
> > I think it's better if WaitCommEvent() returns with EV_TXEMPTY even if there 
> > has no new data been sent in between:
>
> That means that WaitCommEvent(EV_TXEMPTY) without any prior WriteFile
> would always return success and signal the EV_TXEMPTY event. My tests
> show that WaitCommEvent(EV_TXEMPTY) fails with a timeout in this case.
> Since the serial device is very slow it should be unlikely that after
> successful WriteFile() with some data WaitCommEvent() sees an already
> empty transmitter's output queue.

One of the solutions to this would be that WriteFile sets a flag for a
being written handle indicating that there were data pending for this
handle, then WaitCommEvent(EV_TXEMPTY) in the case of empty output queue
would see that flag, clear it and set EV_TXEMPTY flag in the events mask.

That would also explain why SetCommMask() called after WriteFile() makes
WaitCommEvent(EV_TXEMPTY) fail with a timeout in some testbot VMs, in that
case SetCommMask() would also clear the data pending write flag.

[4/4] ntdll: Properly set flag which indicates buffer empty state.

[Wolfgang Walter]

Am Donnerstag, 29. August 2013, 10:47:46 schrieb Dmitry Timoshkov:
> Wolfgang Walter  wrote:
> > I think that happens:
> > - application writes data to com port.
> > - all is written, serial buffer is empty
> > - application calls  WaitCommEvent()
> > - wait_on() is called
> > - wait_on() calls get_irq_info()
> > - get_irq_info() sets commio->irq_info->temt = 1
> > - wait_on() calls check_events() and uses sets commio->irq_info for old an
> >
> > new * so old->temt == new->temt and EV_TXEMPTY is not set
> > - if there are no other events (in real world basically EV_RXCHAR):
> > - wait_for_event() is startet with commio->irq_info->temt set to one
> > - wait_for_event() calls get_irq_info() with new_irq_info()
> > - get_irq_info() sets new_irq_info->temt = 1 because the buffer is still
> >
> > empty * wait_for_event() calls check_events() with new_irq_info and
> > commio->irq_info * again check_events() will not set EV_TXEMPTY as both
> > have temt == 1
> >
> > It seems that we do not recover from that hang.
> >
> > Please correct me if I misread the code and I'm wrong.
> >
> > I think it's better if WaitCommEvent() returns with EV_TXEMPTY even if
> > there
> > has no new data been sent in between:
>
> That means that WaitCommEvent(EV_TXEMPTY) without any prior WriteFile
> would always return success and signal the EV_TXEMPTY event. My tests
> show that WaitCommEvent(EV_TXEMPTY) fails with a timeout in this case.
> Since the serial device is very slow it should be unlikely that after
> successful WriteFile() with some data WaitCommEvent() sees an already
> empty transmitter's output queue.

Maybe for tests. But the application which fails here (with vanilla wine) 
hangs because it waits for EV_TXEMPTY.

Basically it writes data to several serial ports, then write to files and then 
waits for the EV_TXEMPTYs.

Regards,