tcgetattr hangs
Kustaa Nyholm
Kustaa.Nyholm at planmeca.com
Fri Jun 1 18:03:18 UTC 2012
On 5/29/12 14:02, "Konstantin Belousov" <kostikbel at gmail.com> wrote:
>>Here is a piece of our debug log that shows the calls from Java to the
>>native
>>API showing the end of the successful Test2 and the hang at the
>>beginning
>>of Test3:
>>log: > select(9,[8],[],[],jtermios.TimeVal at 6f507fb2)
>>.................................. OK average speed log: <
>>select(9,[],[],[],jtermios.TimeVal at 6f507fb2) => 0
>>log: > select(9,[8],[],[],jtermios.TimeVal at 6f507fb2)
>>18241 b/sec at baud rate 19200
>>log: > fcntl(8, 3, 0)
>>log: < fcntl(8, 3, 0) => 2
>>log: > fcntl(8, 4, 6)
>>log: < fcntl(8, 4, 6) => 0
>>log: > close(8)
>>log: < close(8) => 0
>>Test3 - transmit all characters log: <
>>select(9,[8],[],[],jtermios.TimeVal at 6f507fb2) => -1
>>log: > open('cuau0',00008006)
>>log: < open('cuau0',00008006) => 8
>>log: > close(8)
>>log: < close(8) => 0
>>log: > open('cuau0',00008006)
>>log: < open('cuau0',00008006) => 8
>>log: > fcntl(8, 3, 0)
>>log: < fcntl(8, 3, 0) => 6
>>log: > fcntl(8, 4, 2)
>>log: < fcntl(8, 4, 2) => 0
>>log: > tcgetattr(8,jtermios.Termios at 5a77a7f9)
>>All comments welcome.
>
>Verify that the thread indeed hang in ioctl, executed on the right
>file descriptor and TIOCGETA ioctl command. You may use ktrace(1)
>or truss(1) for this.
>
>If ioctl(TIOCGETA) is indeed what was called, then look at the in-kernel
>backtrace of the hung thread with procstat -kk <pid> command.
>
Ok, we managed to do a ktrace and below is the relevant part of the log.
It looks like the ioctl(TIOCGETA)/tcgetattr was indeed succesfully
completed but the Java code then hangs (or atleast we are
not able to see anything on the Java side of things, evidently
something keeps causing entries in the log.
Can anyone hazard an opinion on what the log is showing?
br Kusti
22683 100350 java RET F64 sigaction 0
22683 100350 java CALL F64
sigaction(SIGSEGV,0x7fffffbfe030,0x7fffffbfe010)
22683 100350 java RET F64 sigaction 0
22683 100350 java CALL F64
sigaction(SIGBUS,0x7fffffbfe030,0x7fffffbfe010)
22683 100350 java RET F64 sigaction 0
22683 100350 java CALL F64 sigprocmask(SIG_BLOCK,0,0x80fb60228)
22683 100350 java RET F64 sigprocmask 0
22683 100350 java CALL F64
sigaction(SIGSEGV,0x7fffffbfe030,0x7fffffbfe010)
22683 100350 java RET F64 sigaction 0
22683 100350 java CALL F64
sigaction(SIGBUS,0x7fffffbfe030,0x7fffffbfe010)
22683 100350 java RET F64 sigaction 0
22683 100350 java CALL F64
sigaction(SIGSEGV,0x7fffffbfe100,0x7fffffbfe0e0)
22683 100350 java RET F64 sigaction 0
22683 100350 java CALL F64
sigaction(SIGBUS,0x7fffffbfe100,0x7fffffbfe0e0)
22683 100350 java RET F64 sigaction 0
22683 100350 java CALL F64 sigprocmask(SIG_BLOCK,0,0x80fb60228)
22683 100350 java RET F64 sigprocmask 0
22683 100350 java CALL F64 ioctl(0x8,TIOCGETA,0x80fe4f940)
22683 100350 java RET F64 ioctl 0
22683 100350 java CALL F64
sigaction(SIGSEGV,0x7fffffbfe100,0x7fffffbfe0e0)
22683 100350 java RET F64 sigaction 0
22683 100350 java CALL F64
sigaction(SIGBUS,0x7fffffbfe100,0x7fffffbfe0e0)
22683 100350 java RET F64 sigaction 0
after which following keeps repeating endlessly:
22683 100350 java PSIG F64 SIGSEGV caught handler=0x80fa4f9f0
mask=0x4 code=0x1
22683 100350 java CALL F64 sigprocmask(SIG_SETMASK,0x7fffffbfde30,0)
22683 100350 java RET F64 sigprocmask 0
22683 100350 java CALL F64
sigaction(SIGSEGV,0x7fffffbfe100,0x7fffffbfe0e0)
22683 100350 java RET F64 sigaction 0
22683 100350 java CALL F64
sigaction(SIGBUS,0x7fffffbfe100,0x7fffffbfe0e0)
22683 100350 java RET F64 sigaction 0
22683 100350 java PSIG F64 SIGSEGV caught handler=0x80fa4f9f0
mask=0x4 code=0x1
22683 100350 java CALL F64 sigprocmask(SIG_SETMASK,0x7fffffbfdca0,0)
22683 100350 java RET F64 sigprocmask 0
22683 100350 java CALL F64
sigaction(SIGSEGV,0x7fffffbfe100,0x7fffffbfe0e0)
22683 100350 java RET F64 sigaction 0
22683 100350 java CALL F64
sigaction(SIGBUS,0x7fffffbfe100,0x7fffffbfe0e0)
22683 100350 java RET F64 sigaction 0
22683 100350 java PSIG F64 SIGSEGV caught handler=0x80fa4f9f0
mask=0x4 code=0x1
So acting on this suggestion:
>"If ioctl(TIOCGETA) is indeed what was called, then look at the in-kernel
>backtrace of the hung thread with procstat -kk<pid> command."
This is from an different hang, though:
procstat -kk 19315
PID TID COMM TDNAME KSTACK
19315 100112 java - <running>
19315 100443 java - mi_switch+0x186
sleepq_catch_signals+0x31c sleepq_timedwait_sig+0x19 _sleep+0x2d1
do_cv_wait+0x630 __umtx_op_cv_wait+0x66 amd64_syscall+0x24f
Xfast_syscall+0xfc
19315 100519 java - mi_switch+0x186
sleepq_catch_signals+0x31c sleepq_wait_sig+0x16 _sleep+0x29a
do_cv_wait+0x861 __umtx_op_cv_wait+0x66 amd64_syscall+0x24f
Xfast_syscall+0xfc
19315 100622 java - mi_switch+0x186
sleepq_catch_signals+0x31c sleepq_wait_sig+0x16 _sleep+0x29a
do_cv_wait+0x861 __umtx_op_cv_wait+0x66 amd64_syscall+0x24f
Xfast_syscall+0xfc
19315 100645 java - mi_switch+0x186
sleepq_catch_signals+0x31c sleepq_wait_sig+0x16 _sleep+0x29a
do_wait+0x71a __umtx_op_wait_uint_private+0x6e amd64_syscall+0x24f
Xfast_syscall+0xfc
19315 100708 java initial thread mi_switch+0x186
sleepq_catch_signals+0x31c sleepq_wait_sig+0x16 _sleep+0x29a
do_wait+0x71a __umtx_op_wait+0x68 amd64_syscall+0x24f Xfast_syscall+0xfc
19315 100763 java - mi_switch+0x186
sleepq_catch_signals+0x31c sleepq_wait_sig+0x16 _sleep+0x29a
do_cv_wait+0x861 __umtx_op_cv_wait+0x66 amd64_syscall+0x24f
Xfast_syscall+0xfc
19315 100769 java - mi_switch+0x186
sleepq_catch_signals+0x31c sleepq_wait_sig+0x16 _sleep+0x29a
do_cv_wait+0x861 __umtx_op_cv_wait+0x66 amd64_syscall+0x24f
Xfast_syscall+0xfc
19315 100775 java - mi_switch+0x186
sleepq_catch_signals+0x31c sleepq_wait_sig+0x16 _sleep+0x29a
do_cv_wait+0x861 __umtx_op_cv_wait+0x66 amd64_syscall+0x24f
Xfast_syscall+0xfc
19315 100789 java - mi_switch+0x186
sleepq_catch_signals+0x31c sleepq_timedwait_sig+0x19 _sleep+0x2d1
do_cv_wait+0x630 __umtx_op_cv_wait+0x66 amd64_syscall+0x24f
Xfast_syscall+0xfc
More information about the freebsd-java
mailing list