问题背景
在实现git上的开源串口驱动api(android_serialport_api)的LoopBackActivity例程的时候,意外发现一个奇怪的现象:有时候启动LoopBackActivity时,第一个字节会Lost(Corrupted为0)。进入调试模式,断点打在接收线程的onDataReceived()里,发现确实有收到第一个值为"0"的字节,并且用示波器抓波形,第一个字节也确实发出了。那么是什么原因造成的呢?
中间猜想
调试发现收到第一个字节时,接收线程里的mValueToSend(即当前发送字符)不是0(且mOutGoing和mInComing都不是0),而是一个-127~128的一个“随机值”(每次Lost时该值都不一样),更奇怪的是接收线程里mCorrupted确实加1了,但是到了发送线程里mCorrupted又变成了0(mOutGoing和mInComing也都是0,只有mLost加1)。这个现象让我不免觉得是两个线程对变量的读取不一致造成的,于是上网查资料得知java线程确实可能有这个问题:java多线程解读二(内存篇)
Java内存模型中规定了所有的变量都存储在主内存中,每条线程还有自己的虚拟内存。线程的虚拟内存中保存了该线程使用到的变量到主内存副本拷贝。线程对变量的所有操作(读取、赋值)都必须在自己的虚拟内存中进行,而不能直接读写主内存中的变量。不同线程之间无法直接访问对方虚拟内存中的变量,线程间变量值的传递均需要在主内存来完成。
如何避免多线程对变量访问的不同步,java 中如何避免多线程不安全 里面说到可以使用volatile或同步锁:
使用volatile变量
volatile变量内存语义
1. 当对一个volatile变量进行写操作的时候,JMM会把该线程对应的本地内存中的共享变量的值刷新到主内存中。
2. 当一个线程读volatile变量时,JMM会把该线程对应的本地内存变量置为无效,要求线程从主内存中读该变量。
使用锁(synchronized,可重入锁)
锁的内存语义:
1.当线程释放锁时,JMM会把该线程对应的本地内存中的共享变量刷新到主内存中。
2. 当线程获取锁时,JMM会把当前线程拥有的本地内存共享变量置为无效,线程从主内存中读取共享变量。
但是程序里本来就使用了synchronized关键字来进行接收线程和发送线程的同步,应该是不会有这个问题的,但是不放心我又在共享变量前加了volatile关键字,结果不出意料的还是会出现第一个字节lost的问题。说明不是这个原因造成的。继续寻找原因。
问题症结
仔细观察调试信息,神奇地发现接收线程和发送线程加锁的对象mByteReceivedBackSemaphore居然不是同一个(地址不同)!进而发现两个线程所属于的activity都不是一个实例!于是有一个大胆的猜测:出问题的接收线程所属的activity会不会是上一次返回的activity! 两次打开观察调试信息,真的是这样!如下:
第一个字节“lost”的SendingThread所属的activity,看到所有变量都是"0"
收到第一个字节的onDataReceived()(在mReadThread中调用)所属的activity,看到mInComing并不是"0"
两个不属于同一个activity,synchronized的对象mByteReceivedBackSemaphore当然也不一样!
然后运行一段时间后,再在onDataReceived()中暂停却发现activity和SendingThread一样了。
关闭后再打开一次,再次出现第一个字节"lost"的问题,此时接收线程所属于的activity:
果然和第一次的发送线程的activity是同一个!!原因找到了,两个activity实例,当然变量都不一样,mValueToSend的奇怪“随机值”其实是上一个activity发送的最后一个字符。
虽然致病因子找到了,但是紧接着问题就来了:明明按下返回键销毁了活动,为什么接收线程却苟活了下来?而且在销毁活动时明明都关闭了串口,怎么它的InputStream还能接收?
在网上查找线程没有正常退出的原因,得知关闭线程通常有两种:
1、 在线程中加入一个成员变量,当一个flag使用。在线程run()方法中轮流去检查这个变量,变量变化时就退出这个线程。
2、 第一个方法虽然可以处理好,不过,在有阻塞线程的语句的时候往往不能处理好,因为线程被阻塞了(比如调用wait(), sleep(), join()三个方法之一),它便不能核查成员变量,就不能停止。这个时候可以使用thread.interrupt()方法。Interrupt()方法只能解决抛出InterruptedException异常的阻塞。
那么遇到一些其他的io阻塞怎么处理呢?有些IO接口也是可以被interrpted的(指能够抛出CloseByInterruptException的IO Operation)。关于interrupt():
public void interrupt ()
Added in API level 1
Posts an interrupt request to this Thread. The behavior depends on the state of this Thread:
- Threads blocked in one of Object‘s wait() methods or one of Thread‘s join() or sleep() methods will be woken up, their interrupt status will be cleared, and they receive an InterruptedException.
- Threads blocked in an I/O operation of an InterruptibleChannel will have their interrupt status set and receive an ClosedByInterruptException. Also, the channel will be closed.
- Threads blocked in a Selector will have their interrupt status set and return immediately. They don‘t receive an exception in this case.
See Also
一开始读这些内容,我并没有获取到什么有帮助的信息,因为在onDestroy()时已经调用了mReadThread.interrupt(),按理说mReadThread在检测到它的interrupt标志应该就能及时退出呀。如下:
1 private class ReadThread extends Thread { 2 3 @Override 4 5 public void run() { 6 7 super.run(); 8 9 byte[] buffer = new byte[64]; 10 11 int size; 12 13 while(!isInterrupted()) { 14 15 try { 16 17 if (mInputStream == null) return; 18 19 size = mInputStream.read(buffer); 20 21 if (size > 0) { 22 23 onDataReceived(buffer, size); 24 25 } 26 27 } catch (IOException e) { 28 29 e.printStackTrace(); 30 31 return; 32 33 } 34 35 } 36 37 Log.d(TAG, "mReadThread quits while at" + System.currentTimeMillis()); 38 39 } 40 41 }
在反复看那些文字后,我突然对“io阻塞”来了灵感,这才意识到,串口的InputStream.read()方法就是io操作呀,并且还会阻塞呀!
public abstract int read ()
Added in API level 1
Reads a single byte from this stream and returns it as an integer in the range from 0 to 255. Returns -1 if the end of the stream has been reached. Blocks until one byte has been read, the end of the source stream is detected or an exception is thrown.
Throws
IOException
if the stream is closed or another IOException occurs.public int read (byte[] buffer, int byteOffset, int byteCount)
Added in API level 1
Reads up to byteCount bytes from this stream and stores them in the byte array buffer starting at byteOffset. Returns the number of bytes actually read or -1 if the end of the stream has been reached.
Throws
IndexOutOfBoundsException
if byteOffset < 0 || byteCount < 0 || byteOffset + byteCount > buffer.length.
IOException
if the stream is closed or another IOException occurs.
即没有字节就会一直block,有数据就会返回接收到的实际字节数量。
于是乎我茅塞顿开:
1)接收线程之所于没有及时退出,正是因为SendingThread退出后,没有字节流进来,mReadThread就一直卡在read()方法,根本没办法去检查isInterrupt().
2)串口虽然关闭,但是关闭串口前,接收线程就已经运行到了mInputStream.read(buffer),并且阻塞在这,也就是说接收通道一直存在,一旦有一个字符进来,当然是能读到。
3)下一次启动活动时打开的SendgingThread发送的第一个字节就被这个mReadThread残留的接收通道抓到了,然后它检查while()条件发现isInterrupted()成立,这才退出历史舞台。后面的字节都被新活动的mReadThread正常获取。所以后面再在onDataReceived()中暂停就发现activity和SendingThread的activity一样了。
4)有时候又可以正常退出的原因是,SendingThread在sleep()时抛出InterruptException清除了interrupt标志,因此并没有立即退出while循环,继续发出一个字符,此时串口还没来得及关闭,接收线程在收到这个字节后检查while(!isInterrupted())不满足,就迅速退出run()了。
解决办法
给read()方法加上超时设置。需要修改linux底层串口终端配置,在SerialPort.c里添加以下代码:
1 // 设置read超时 2 3 LOGD("before set, vtime is %d", cfg.c_cc[VTIME]); 4 5 LOGD("before set, vmin is %d", cfg.c_cc[VMIN]); 6 7 cfg.c_cc[VTIME] = 10; 8 9 cfg.c_cc[VMIN] = 0; 10 11 LOGD("after set, vtime is %d", cfg.c_cc[VTIME]); 12 13 LOGD("after set, vmin is %d", cfg.c_cc[VMIN]);
关于VTIME和VMIN的说明参考这篇博文 Linux串口中的超时设置
通过log打印得知设置前原来的VTIME为0,VMIN为1,即至少读到1个字节才会返回否则一直阻塞。
现在我们来检验一下增加超时后的效果,通过log打印信息还可以顺便分析未设置超时时出错的具体过程:
完整LoopBackActivity代码如下:
LoopBackActivity.java
1 public class LoopBackActivity extends SerialPortActivity { 2 3 4 5 private static final String TAG = "LoopBackActivity"; 6 7 8 9 volatile byte mValueToSend; 10 11 volatile boolean mByteReceivedBack; 12 13 final Object mByteReceivedBackSemaphore = new Object(); 14 15 16 17 volatile Integer mInComing = new Integer(0); 18 19 volatile Integer mOutGoing = new Integer(0); 20 21 volatile Integer mLost = new Integer(0); 22 23 volatile Integer mCorrupted = new Integer(0); 24 25 26 27 private SendingThread mSendingThread; 28 29 30 31 TextView mValueSentText; 32 33 TextView mInComingText; 34 35 TextView mOutGoingText; 36 37 TextView mLostText; 38 39 TextView mCorruptedText; 40 41 42 43 class SendingThread extends Thread { 44 45 @Override 46 47 public void run() { 48 49 while (!isInterrupted()) { 50 51 synchronized (mByteReceivedBackSemaphore) { 52 53 try { 54 55 Thread.sleep(100); 56 57 } catch (InterruptedException e) { 58 59 Log.d(TAG, "run: SendingThread is interrupted at " + System.currentTimeMillis()); 60 61 } 62 63 mByteReceivedBack = false; // clear flag before sending 64 65 if (mOutputStream != null) { 66 67 try { 68 69 mOutputStream.write(mValueToSend); 70 71 } catch (IOException e) { 72 73 e.printStackTrace(); 74 75 return; 76 77 } 78 79 } else return; 80 81 mOutGoing++; 82 83 Log.d(TAG, Thread.currentThread().getName() + " has sent " + mValueToSend 84 85 + " at " + System.currentTimeMillis()); 86 87 try { 88 89 mByteReceivedBackSemaphore.wait(100); 90 91 } catch (InterruptedException e) {} 92 93 Log.d(TAG, Thread.currentThread().getName() + " resumes at " + System.currentTimeMillis()); 94 95 if (mByteReceivedBack == true) { // send success 96 97 mInComing++; 98 99 } else { 100 101 mLost++; 102 103 } 104 105 106 107 // show results on UI 108 109 runOnUiThread(new Runnable() { 110 111 @Override 112 113 public void run() { 114 115 mValueSentText.setText(String.valueOf(mValueToSend)); 116 117 mInComingText.setText(String.format(Locale.getDefault(),"%d",mInComing)); 118 119 mOutGoingText.setText(String.format(Locale.getDefault(),"%d",mOutGoing)); 120 121 mLostText.setText(String.format(Locale.getDefault(),"%d",mLost)); 122 123 mCorruptedText.setText(String.format(Locale.getDefault(),"%d",mCorrupted)); 124 125 } 126 127 }); 128 129 } 130 131 } 132 133 } 134 135 } 136 137 138 139 @Override 140 141 protected void onDataReceived(byte[] buffer, int size) { 142 143 synchronized (mByteReceivedBackSemaphore) { 144 145 for (int i = 0; i < size; i++) { 146 147 if (buffer[i] == mValueToSend && mByteReceivedBack == false) { 148 149 mValueToSend++; 150 151 mByteReceivedBack = true; 152 153 mByteReceivedBackSemaphore.notify(); 154 155 Log.d(TAG, Thread.currentThread().getName() + " has notified at " + System.currentTimeMillis()); 156 157 } else { 158 159 mCorrupted++; 160 161 } 162 163 } 164 165 } 166 167 } 168 169 170 171 @Override 172 173 protected void onCreate(Bundle savedInstanceState) { 174 175 mValueToSend = 0; 176 177 super.onCreate(savedInstanceState); 178 179 setContentView(R.layout.activity_loop_back); 180 181 mInComingText = (TextView)findViewById(R.id.TextViewIncomingValue); 182 183 mOutGoingText = (TextView)findViewById(R.id.TextViewOutgoingValue); 184 185 mLostText = (TextView)findViewById(R.id.TextViewLostValue); 186 187 mCorruptedText = (TextView)findViewById(R.id.TextViewCorruptedValue); 188 189 mValueSentText = (TextView)findViewById(R.id.TextViewCurrValueSent); 190 191 mSendingThread = new SendingThread(); 192 193 mSendingThread.start(); 194 195 } 196 197 198 199 @Override 200 201 protected void onDestroy() { 202 203 if (mSendingThread != null) { 204 205 mSendingThread.interrupt(); 206 207 } 208 209 super.onDestroy(); 210 211 } 212 213 } 214 215
LoopBackActivity
SerialPortActivity.java
1 public abstract class SerialPortActivity extends AppCompatActivity { 2 3 4 5 private static final String TAG = "SerialPortActivity"; 6 7 8 9 protected Application mApplication; 10 11 protected SerialPort mSerialPort; 12 13 protected OutputStream mOutputStream; 14 15 private InputStream mInputStream; 16 17 private ReadThread mReadThread; 18 19 20 21 private class ReadThread extends Thread { 22 23 @Override 24 25 public void run() { 26 27 super.run(); 28 29 byte[] buffer = new byte[64]; 30 31 int size; 32 33 while(!isInterrupted()) { 34 35 try { 36 37 if (mInputStream == null) return; 38 39 size = mInputStream.read(buffer); 40 41 if (size > 0) { 42 43 onDataReceived(buffer, size); 44 45 } 46 47 } catch (IOException e) { 48 49 e.printStackTrace(); 50 51 return; 52 53 } 54 55 } 56 57 Log.d(TAG, "mReadThread quits while at" + System.currentTimeMillis()); 58 59 } 60 61 } 62 63 64 65 @Override 66 67 protected void onCreate(Bundle savedInstanceState) { 68 69 super.onCreate(savedInstanceState); 70 71 mApplication = (Application)getApplication(); 72 73 try { 74 75 mSerialPort = mApplication.getSerialPort(); 76 77 mOutputStream = mSerialPort.getOutputStream(); 78 79 mInputStream = mSerialPort.getInputStream(); 80 81 82 83 /* Create a receiving thread */ 84 85 mReadThread = new ReadThread(); 86 87 mReadThread.start(); 88 89 } catch (SecurityException e) { 90 91 DisplayError(R.string.error_security); 92 93 } catch (InvalidParameterException e) { 94 95 DisplayError(R.string.error_configuration); 96 97 } catch (IOException e) { 98 99 DisplayError(R.string.error_unknown); 100 101 } 102 103 104 105 } 106 107 108 109 private void DisplayError (int resourceID) { 110 111 AlertDialog.Builder b = new AlertDialog.Builder (this); 112 113 b.setTitle("Error"); 114 115 b.setMessage(resourceID); 116 117 b.setPositiveButton("OK", new DialogInterface.OnClickListener() { 118 119 @Override 120 121 public void onClick(DialogInterface dialog, int which) { 122 123 SerialPortActivity.this.finish(); 124 125 } 126 127 }); 128 129 b.show(); 130 131 } 132 133 134 135 protected abstract void onDataReceived(byte[] buffer, int size); 136 137 138 139 @Override 140 141 protected void onDestroy() { 142 143 if (mReadThread != null) { 144 145 mReadThread.interrupt(); 146 147 Log.d(TAG, "onDestroy: mReadThread.interrupt() is called at " + System.currentTimeMillis()); 148 149 } 150 151 mApplication.closeSerialPort(); 152 153 Log.d(TAG, "onDestroy: SerialPort is closed at " + System.currentTimeMillis()); 154 155 mSerialPort = null; 156 157 super.onDestroy(); 158 159 } 160 161 } 162 163
SerialPortActivity
不设置read()超时,即VTIME=0, VMIN=1时
mReadThread能正常退出的情况:
01-08 05:41:05.730 23490-23826/com.example.serialporttest D/LoopBackActivity: Thread-329 has sent 22 at 596465738
01-08 05:41:05.730 23490-23825/com.example.serialporttest D/LoopBackActivity: Thread-328 has notified at 596465739
01-08 05:41:05.740 23490-23826/com.example.serialporttest D/LoopBackActivity: Thread-329 resumes at 596465744
01-08 05:41:05.800 23490-23490/com.example.serialporttest D/SerialPortActivity: onDestroy: mReadThread.interrupt() is called at 596465811
01-08 05:41:05.800 23490-23826/com.example.serialporttest D/LoopBackActivity: run: SendingThread is interrupted at 596465812
01-08 05:41:05.800 23490-23826/com.example.serialporttest D/LoopBackActivity: Thread-329 has sent 23 at 596465812
01-08 05:41:05.800 23490-23825/com.example.serialporttest D/LoopBackActivity: Thread-328 has notified at 596465813
01-08 05:41:05.800 23490-23825/com.example.serialporttest D/SerialPortActivity: mReadThread quits while at596465813
01-08 05:41:05.800 23490-23826/com.example.serialporttest D/LoopBackActivity: Thread-329 resumes at 596465814
01-08 05:41:05.800 23490-23490/com.example.serialporttest D/SerialPortActivity: onDestroy: SerialPort is closed at 596465814
01-08 05:41:05.900 23490-23826/com.example.serialporttest W/System.err: at libcore.io.IoBridge.write(IoBridge.java:464)
01-08 05:41:05.910 23490-23826/com.example.serialporttest W/System.err: at java.io.FileOutputStream.write(FileOutputStream.java:187)
01-08 05:41:05.910 23490-23826/com.example.serialporttest W/System.err: at java.io.FileOutputStream.write(FileOutputStream.java:192)
01-08 05:41:05.910 23490-23826/com.example.serialporttest W/System.err: at com.example.serialporttest.LoopBackActivity$SendingThread.run(LoopBackActivity.java:45)
01-08 05:41:05.910 23490-23826/com.example.serialporttest W/System.err: at libcore.io.Posix.writeBytes(Native Method)
01-08 05:41:05.910 23490-23826/com.example.serialporttest W/System.err: at libcore.io.Posix.write(Posix.java:202)
01-08 05:41:05.910 23490-23826/com.example.serialporttest W/System.err: at libcore.io.BlockGuardOs.write(BlockGuardOs.java:197)
01-08 05:41:05.910 23490-23826/com.example.serialporttest W/System.err: at libcore.io.IoBridge.write(IoBridge.java:459)
活动销毁时, 主线程中mReadThread.interrupt()先被调用,然后sleep中的SendingThread被interrupted后有幸发出最后一个字节"23",mReadThread迅速捕捉到这个字节,发现自己中断标志置位,于是结束运行,最后串口才被关闭,SendingThread试图再次发送字节发生write异常然后结束运行。所以不会产生任何历史遗留问题。
再看mReadThread没能及时结束的情况:
异常退出1
01-08 05:43:48.960 23490-26112/com.example.serialporttest D/LoopBackActivity: Thread-331 has sent 53 at 596628972
01-08 05:43:48.960 23490-26111/com.example.serialporttest D/LoopBackActivity: Thread-330 has notified at 596628972
01-08 05:43:48.960 23490-26112/com.example.serialporttest D/LoopBackActivity: Thread-331 resumes at 596628974
01-08 05:43:49.010 23490-26112/com.example.serialporttest D/LoopBackActivity: run: SendingThread is interrupted at 596629017
01-08 05:43:49.010 23490-26112/com.example.serialporttest D/LoopBackActivity: Thread-331 has sent 54 at 596629018
01-08 05:43:49.010 23490-26111/com.example.serialporttest D/LoopBackActivity: Thread-330 has notified at 596629019
01-08 05:43:49.010 23490-26112/com.example.serialporttest D/LoopBackActivity: Thread-331 resumes at 596629019
01-08 05:43:49.010 23490-23490/com.example.serialporttest D/SerialPortActivity: onDestroy: mReadThread.interrupt() is called at 596629021
01-08 05:43:49.010 23490-23490/com.example.serialporttest D/SerialPortActivity: onDestroy: SerialPort is closed at 596629022
01-08 05:43:49.110 23490-26112/com.example.serialporttest W/System.err: at libcore.io.IoBridge.write(IoBridge.java:464)
01-08 05:43:49.110 23490-26112/com.example.serialporttest W/System.err: at java.io.FileOutputStream.write(FileOutputStream.java:187)
01-08 05:43:49.110 23490-26112/com.example.serialporttest W/System.err: at java.io.FileOutputStream.write(FileOutputStream.java:192)
01-08 05:43:49.110 23490-26112/com.example.serialporttest W/System.err: at com.example.serialporttest.LoopBackActivity$SendingThread.run(LoopBackActivity.java:45)
01-08 05:43:49.110 23490-26112/com.example.serialporttest W/System.err: at libcore.io.Posix.writeBytes(Native Method)
01-08 05:43:49.110 23490-26112/com.example.serialporttest W/System.err: at libcore.io.Posix.write(Posix.java:202)
01-08 05:43:49.110 23490-26112/com.example.serialporttest W/System.err: at libcore.io.BlockGuardOs.write(BlockGuardOs.java:197)
01-08 05:43:49.110 23490-26112/com.example.serialporttest W/System.err: at libcore.io.IoBridge.write(IoBridge.java:459)
01-08 05:48:22.620 23490-30131/com.example.serialporttest D/LoopBackActivity: Thread-333 has sent 0 at 596902634
01-08 05:48:22.620 23490-26111/com.example.serialporttest D/SerialPortActivity: mReadThread quits while at596902634
01-08 05:48:22.720 23490-30131/com.example.serialporttest D/LoopBackActivity: Thread-333 resumes at 596902734
01-08 05:48:22.820 23490-30131/com.example.serialporttest D/LoopBackActivity: Thread-333 has sent 0 at 596902835
01-08 05:48:22.820 23490-30130/com.example.serialporttest D/LoopBackActivity: Thread-332 has notified at 596902835
01-08 05:48:22.830 23490-30131/com.example.serialporttest D/LoopBackActivity: Thread-333 resumes at 596902836
活动销毁时,sleep中的SendingThread(Thread-331)首先被interrupted后发出最后一个字节,mReadThread(Thread-330)迅速捕捉到这个字节,可惜此后它的中断标志才被置位,也就是说在中断标志置位前,它已经卡在read()了,直到新的SendingThread(Thread-333)发出第一个字节后,mReadThread(Thread-330)才能结束运行,此后新的mReadThread(Thread-332)才能接收到重发的第一个字节以及后面的字节。
异常退出2
01-08 06:00:14.440 23490-8067/com.example.serialporttest D/LoopBackActivity: Thread-335 has sent 22 at 597614449
01-08 06:00:14.440 23490-8066/com.example.serialporttest D/LoopBackActivity: Thread-334 has notified at 597614450
01-08 06:00:14.440 23490-8067/com.example.serialporttest D/LoopBackActivity: Thread-335 resumes at 597614450
01-08 06:00:14.480 23490-23490/com.example.serialporttest D/SerialPortActivity: onDestroy: mReadThread.interrupt() is called at 597614492
01-08 06:00:14.480 23490-8067/com.example.serialporttest D/LoopBackActivity: run: SendingThread is interrupted at 597614493
01-08 06:00:14.480 23490-23490/com.example.serialporttest D/SerialPortActivity: onDestroy: SerialPort is closed at 597614493
01-08 06:00:14.480 23490-8067/com.example.serialporttest W/System.err: at libcore.io.IoBridge.write(IoBridge.java:464)
01-08 06:00:14.480 23490-8067/com.example.serialporttest W/System.err: at java.io.FileOutputStream.write(FileOutputStream.java:187)
01-08 06:00:14.480 23490-8067/com.example.serialporttest W/System.err: at java.io.FileOutputStream.write(FileOutputStream.java:192)
01-08 06:00:14.480 23490-8067/com.example.serialporttest W/System.err: at com.example.serialporttest.LoopBackActivity$SendingThread.run(LoopBackActivity.java:45)
01-08 06:00:14.480 23490-8067/com.example.serialporttest W/System.err: at libcore.io.Posix.writeBytes(Native Method)
01-08 06:00:14.480 23490-8067/com.example.serialporttest W/System.err: at libcore.io.Posix.write(Posix.java:202)
01-08 06:00:14.490 23490-8067/com.example.serialporttest W/System.err: at libcore.io.BlockGuardOs.write(BlockGuardOs.java:197)
01-08 06:00:14.490 23490-8067/com.example.serialporttest W/System.err: at libcore.io.IoBridge.write(IoBridge.java:459)
01-08 06:02:52.290 23490-10364/com.example.serialporttest D/LoopBackActivity: Thread-337 has sent 0 at 597772299
01-08 06:02:52.290 23490-8066/com.example.serialporttest D/SerialPortActivity: mReadThread quits while at597772300
01-08 06:02:52.390 23490-10364/com.example.serialporttest D/LoopBackActivity: Thread-337 resumes at 597772400
01-08 06:02:52.490 23490-10364/com.example.serialporttest D/LoopBackActivity: Thread-337 has sent 0 at 597772501
01-08 06:02:52.490 23490-10359/com.example.serialporttest D/LoopBackActivity: Thread-336 has notified at 597772501
01-08 06:02:52.490 23490-10364/com.example.serialporttest D/LoopBackActivity: Thread-337 resumes at 597772501
活动销毁时, 主线程中mReadThread.interrupt()先被调用,然后sleep中的SendingThread被interrupted,还没来得及发出下一个字节,串口就先关闭了,mReadThread等不来这个字节,只能卡在read()了,等待新的SendingThread来拯救它。
异常退出3
01-08 06:15:23.450 23490-21140/com.example.serialporttest D/LoopBackActivity: Thread-368 has sent 55 at 598523466
01-08 06:15:23.460 23490-21139/com.example.serialporttest D/LoopBackActivity: Thread-367 has notified at 598523466
01-08 06:15:23.460 23490-21140/com.example.serialporttest D/LoopBackActivity: Thread-368 resumes at 598523466
01-08 06:15:23.530 23490-23490/com.example.serialporttest D/SerialPortActivity: onDestroy: mReadThread.interrupt() is called at 598523542
01-08 06:15:23.530 23490-23490/com.example.serialporttest D/SerialPortActivity: onDestroy: SerialPort is closed at 598523542
01-08 06:15:23.530 23490-21140/com.example.serialporttest D/LoopBackActivity: run: SendingThread is interrupted at 598523543
01-08 06:15:23.530 23490-21140/com.example.serialporttest W/System.err: at libcore.io.IoBridge.write(IoBridge.java:464)
01-08 06:15:23.530 23490-21140/com.example.serialporttest W/System.err: at java.io.FileOutputStream.write(FileOutputStream.java:187)
01-08 06:15:23.530 23490-21140/com.example.serialporttest W/System.err: at java.io.FileOutputStream.write(FileOutputStream.java:192)
01-08 06:15:23.530 23490-21140/com.example.serialporttest W/System.err: at com.example.serialporttest.LoopBackActivity$SendingThread.run(LoopBackActivity.java:45)
01-08 06:15:23.530 23490-21140/com.example.serialporttest W/System.err: at libcore.io.Posix.writeBytes(Native Method)
01-08 06:15:23.530 23490-21140/com.example.serialporttest W/System.err: at libcore.io.Posix.write(Posix.java:202)
01-08 06:15:23.540 23490-21140/com.example.serialporttest W/System.err: at libcore.io.BlockGuardOs.write(BlockGuardOs.java:197)
01-08 06:15:23.540 23490-21140/com.example.serialporttest W/System.err: at libcore.io.IoBridge.write(IoBridge.java:459)
01-08 06:16:43.200 23490-22357/com.example.serialporttest D/LoopBackActivity: Thread-370 has sent 0 at 598603213
01-08 06:16:43.200 23490-21139/com.example.serialporttest D/SerialPortActivity: mReadThread quits while at598603215
01-08 06:16:43.310 23490-22357/com.example.serialporttest D/LoopBackActivity: Thread-370 resumes at 598603316
01-08 06:16:43.410 23490-22357/com.example.serialporttest D/LoopBackActivity: Thread-370 has sent 0 at 598603416
01-08 06:16:43.410 23490-22356/com.example.serialporttest D/LoopBackActivity: Thread-369 has notified at 598603417
01-08 06:16:43.410 23490-22357/com.example.serialporttest D/LoopBackActivity: Thread-370 resumes at 598603418
活动销毁时, 主线程中mReadThread.interrupt()先被调用,紧接着串口就被关闭,然后SendingThread才缓缓醒来,当然无法发出字节了,mReadThread等不来这个字节,只能卡在read()了,等待新的SendingThread来拯救它。
可见,异常退出的情况有很多种,都是不能同时满足“中断标志先置位然后收到一个字节退出read()阻塞状态”这两个条件,这是由于多线程并发运行的随机性造成的,不打印出来还真不知道原来多线程并发运行时这么“随意”哈。
那么设置了超时后带来的效果,VTIME=10, VMIN=0, 即超时10*100ms后read()返回
先看mReadThread正常结束时,和不加超时设置时一样,超时还没发挥出它的威力:
01-08 05:33:42.240 29330-17495/com.example.serialporttest D/LoopBackActivity: Thread-333 has sent 49 at 596022254
01-08 05:33:42.240 29330-17494/com.example.serialporttest D/LoopBackActivity: Thread-332 has notified at 596022255
01-08 05:33:42.250 29330-17495/com.example.serialporttest D/LoopBackActivity: Thread-333 resumes at 596022262
01-08 05:33:42.330 29330-29330/com.example.serialporttest D/SerialPortActivity: onDestroy: mReadThread.interrupt() is called at 596022344
01-08 05:33:42.330 29330-17495/com.example.serialporttest D/LoopBackActivity: run: SendingThread is interrupted at 596022345
01-08 05:33:42.330 29330-17495/com.example.serialporttest D/LoopBackActivity: Thread-333 has sent 50 at 596022346
01-08 05:33:42.340 29330-17494/com.example.serialporttest D/LoopBackActivity: Thread-332 has notified at 596022346
01-08 05:33:42.340 29330-17494/com.example.serialporttest D/SerialPortActivity: mReadThread quits while at596022347
01-08 05:33:42.340 29330-17495/com.example.serialporttest D/LoopBackActivity: Thread-333 resumes at 596022348
01-08 05:33:42.340 29330-29330/com.example.serialporttest D/SerialPortActivity: onDestroy: SerialPort is closed at 596022350
01-08 05:33:42.440 29330-17495/com.example.serialporttest W/System.err: at libcore.io.IoBridge.write(IoBridge.java:464)
01-08 05:33:42.440 29330-17495/com.example.serialporttest W/System.err: at java.io.FileOutputStream.write(FileOutputStream.java:187)
01-08 05:33:42.440 29330-17495/com.example.serialporttest W/System.err: at java.io.FileOutputStream.write(FileOutputStream.java:192)
01-08 05:33:42.440 29330-17495/com.example.serialporttest W/System.err: at com.example.serialporttest.LoopBackActivity$SendingThread.run(LoopBackActivity.java:45)
01-08 05:33:42.440 29330-17495/com.example.serialporttest W/System.err: at libcore.io.Posix.writeBytes(Native Method)
01-08 05:33:42.440 29330-17495/com.example.serialporttest W/System.err: at libcore.io.Posix.write(Posix.java:202)
01-08 05:33:42.440 29330-17495/com.example.serialporttest W/System.err: at libcore.io.BlockGuardOs.write(BlockGuardOs.java:197)
01-08 05:33:42.440 29330-17495/com.example.serialporttest W/System.err: at libcore.io.IoBridge.write(IoBridge.java:459)
再看mReadThread没能及时结束的情况,超时设置起作用:
01-08 05:14:23.570 29330-780/com.example.serialporttest D/LoopBackActivity: Thread-329 has sent 39 at 594863585
01-08 05:14:23.580 29330-779/com.example.serialporttest D/LoopBackActivity: Thread-328 has notified at 594863586
01-08 05:14:23.580 29330-780/com.example.serialporttest D/LoopBackActivity: Thread-329 resumes at 594863586
01-08 05:14:23.620 29330-29330/com.example.serialporttest D/SerialPortActivity: onDestroy: mReadThread.interrupt() is called at 594863627
01-08 05:14:23.620 29330-29330/com.example.serialporttest D/SerialPortActivity: onDestroy: SerialPort is closed at 594863627
01-08 05:14:23.620 29330-780/com.example.serialporttest D/LoopBackActivity: run: SendingThread is interrupted at 594863627
01-08 05:14:23.620 29330-780/com.example.serialporttest W/System.err: at libcore.io.IoBridge.write(IoBridge.java:464)
01-08 05:14:23.620 29330-780/com.example.serialporttest W/System.err: at java.io.FileOutputStream.write(FileOutputStream.java:187)
01-08 05:14:23.620 29330-780/com.example.serialporttest W/System.err: at java.io.FileOutputStream.write(FileOutputStream.java:192)
01-08 05:14:23.620 29330-780/com.example.serialporttest W/System.err: at com.example.serialporttest.LoopBackActivity$SendingThread.run(LoopBackActivity.java:45)
01-08 05:14:23.620 29330-780/com.example.serialporttest W/System.err: at libcore.io.Posix.writeBytes(Native Method)
01-08 05:14:23.620 29330-780/com.example.serialporttest W/System.err: at libcore.io.Posix.write(Posix.java:202)
01-08 05:14:23.620 29330-780/com.example.serialporttest W/System.err: at libcore.io.BlockGuardOs.write(BlockGuardOs.java:197)
01-08 05:14:23.620 29330-780/com.example.serialporttest W/System.err: at libcore.io.IoBridge.write(IoBridge.java:459)
01-08 05:14:24.580 29330-779/com.example.serialporttest D/SerialPortActivity: mReadThread quits while at594864586
活动销毁时, 主线程中mReadThread.interrupt()先被调用,紧接着串口就被关闭,然后SendingThread才缓缓醒来,当然无法发出字节了,mReadThread等不来这个字节,卡在read(),然而这回没有一直傻等下去,在等了1000ms左右后从read()超时返回,结束运行。(实测超时后,mInputStream.read(buffer)返回-1,说明串口设备的InputStream在超时后会认为达到流末尾)
增加超时后,间隔2秒以上(因为定时没那么准确)看到"quits while"后再重启活动,就绝对不会出现第一个字节“lost”了,但是间隔短于2秒的操作还是有可能"lost"第一个字节,不能接受的话,就把超时时间再设置的短一些吧。