問(wèn)題背景
在實(shí)現(xiàn)android_serialport_api的sample/LoopBackActivity例程的時(shí)候，意外發(fā)現(xiàn)一個(gè)奇怪的現(xiàn)象：有時(shí)候啟動(dòng)LoopBackActivity時(shí)，第一個(gè)字節(jié)會(huì)Lost（Corrupted為0）。進(jìn)入調(diào)試模式，斷點(diǎn)打在接收線程的onDataReceived()里，發(fā)現(xiàn)確實(shí)有收到第一個(gè)值為"0"的字節(jié)，并且用示波器抓波形，第一個(gè)字節(jié)也確實(shí)發(fā)出了。那么是什么原因造成的呢？
中間猜想
調(diào)試發(fā)現(xiàn)收到第一個(gè)字節(jié)時(shí)，接收線程里的mValueToSend(即當(dāng)前發(fā)送字符）不是0（且mOutGoing和mInComing都不是0），而是一個(gè)-127~128的一個(gè)“隨機(jī)值”（每次Lost時(shí)該值都不一樣），更奇怪的是接收線程里mCorrupted確實(shí)加1了，但是到了發(fā)送線程里mCorrupted又變成了0（mOutGoing和mInComing也都是0，只有mLost加1）。這個(gè)現(xiàn)象讓我不免覺(jué)得是兩個(gè)線程對(duì)變量的讀取不一致造成的，于是上網(wǎng)查資料得知java線程確實(shí)可能有這個(gè)問(wèn)題：java多線程解讀二（內(nèi)存篇）
Java內(nèi)存模型中規(guī)定了所有的變量都存儲(chǔ)在主內(nèi)存中，每條線程還有自己的虛擬內(nèi)存。線程的虛擬內(nèi)存中保存了該線程使用到的變量到主內(nèi)存副本拷貝。線程對(duì)變量的所有操作（讀取、賦值）都必須在自己的虛擬內(nèi)存中進(jìn)行，而不能直接讀寫(xiě)主內(nèi)存中的變量。不同線程之間無(wú)法直接訪問(wèn)對(duì)方虛擬內(nèi)存中的變量，線程間變量值的傳遞均需要在主內(nèi)存來(lái)完成。
如何避免多線程對(duì)變量訪問(wèn)的不同步，java 中如何避免多線程不安全 里面說(shuō)到可以使用volatile或同步鎖：
使用volatile變量
volatile變量?jī)?nèi)存語(yǔ)義
1.當(dāng)對(duì)一個(gè)volatile變量進(jìn)行寫(xiě)操作的時(shí)候，JMM會(huì)把該線程對(duì)應(yīng)的本地內(nèi)存中的共享變量的值刷新到主內(nèi)存中。
2.當(dāng)一個(gè)線程讀volatile變量時(shí)，JMM會(huì)把該線程對(duì)應(yīng)的本地內(nèi)存變量置為無(wú)效，要求線程從主內(nèi)存中讀該變量。使用鎖(synchronized,可重入鎖)
鎖的內(nèi)存語(yǔ)義：
1.當(dāng)線程釋放鎖時(shí)，JMM會(huì)把該線程對(duì)應(yīng)的本地內(nèi)存中的共享變量刷新到主內(nèi)存中。
2.當(dāng)線程獲取鎖時(shí)，JMM會(huì)把當(dāng)前線程擁有的本地內(nèi)存共享變量置為無(wú)效，線程從主內(nèi)存中讀取共享變量。
但是程序里本來(lái)就使用了synchronized關(guān)鍵字來(lái)進(jìn)行接收線程和發(fā)送線程的同步，應(yīng)該是不會(huì)有這個(gè)問(wèn)題的，但是不放心我又在共享變量前加了volatile關(guān)鍵字，結(jié)果不出意料的還是會(huì)出現(xiàn)第一個(gè)字節(jié)lost的問(wèn)題。說(shuō)明不是這個(gè)原因造成的。繼續(xù)尋找原因。
問(wèn)題癥結(jié)
仔細(xì)觀察調(diào)試信息，神奇地發(fā)現(xiàn)接收線程和發(fā)送線程加鎖的對(duì)mByteReceivedBackSemaphore居然不是同一個(gè)（地址不同）！進(jìn)而發(fā)現(xiàn)兩個(gè)線程所屬于的activity都不是一個(gè)實(shí)例！于是有一個(gè)大膽的猜測(cè)：出問(wèn)題的接收線程所屬的activity會(huì)不會(huì)是上一次返回的activity! 兩次打開(kāi)觀察調(diào)試信息，真的是這樣！如下：
第一個(gè)字節(jié)“l(fā)ost”的SendingThread所屬的activity，看到所有變量都是"0"
收到第一個(gè)字節(jié)的onDataReceived()(在mReadThread中調(diào)用）所屬的activity,看到mInComing并不是"0"
兩個(gè)不屬于同一個(gè)activity，synchronized的對(duì)象mByteReceivedBackSemaphore當(dāng)然也不一樣！
然后運(yùn)行一段時(shí)間后，再在onDataReceived()中暫停卻發(fā)現(xiàn)activity和SendingThread一樣了。
關(guān)閉后再打開(kāi)一次，再次出現(xiàn)第一個(gè)字節(jié)"lost"的問(wèn)題，此時(shí)接收線程所屬于的activity:
果然和第一次的發(fā)送線程的activity是同一個(gè)！！原因找到了，兩個(gè)activity實(shí)例，當(dāng)然變量都不一樣，mValueToSend的奇怪“隨機(jī)值”其實(shí)是上一個(gè)activity發(fā)送的最后一個(gè)字符。
雖然致病因子找到了，但是緊接著問(wèn)題就來(lái)了：明明按下返回鍵銷(xiāo)毀了活動(dòng)，為什么接收線程卻茍活了下來(lái)？而且在銷(xiāo)毀活動(dòng)時(shí)明明都關(guān)閉了串口，怎么它的InputStream還能接收？
在網(wǎng)上查找線程沒(méi)有正常退出的原因，得知關(guān)閉線程通常有兩種：
1、 在線程中加入一個(gè)成員變量，當(dāng)一個(gè)flag使用。在線程run()方法中輪流去檢查這個(gè)變量，變量變化時(shí)就退出這個(gè)線程。
2、 第一個(gè)方法雖然可以處理好，不過(guò)，在有阻塞線程的語(yǔ)句的時(shí)候往往不能處理好，因?yàn)榫€程被阻塞了（比如調(diào)用wait(), sleep(), join()三個(gè)方法之一），它便不能核查成員變量，就不能停止。這個(gè)時(shí)候可以使用thread.interrupt()方法。Interrupt()方法只能解決拋出InterruptedException異常的阻塞。
那么遇到一些其他的io阻塞怎么處理呢？有些IO接口也是可以被interrpted的（指能夠拋出CloseByInterruptException的IO Operation）。
關(guān)于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- interrupted()
- isInterrupted()
一開(kāi)始讀這些內(nèi)容，我并沒(méi)有獲取到什么有幫助的信息，因?yàn)樵?code>onDestroy()時(shí)已經(jīng)調(diào)用了mReadThread.interrupt()，按理說(shuō)mReadThread在檢測(cè)到它的interrupt標(biāo)志應(yīng)該就能及時(shí)退出呀。如下：
private class ReadThread extends Thread {
@Override
public void run() {
super.run();
byte[] buffer = new byte[64];
int size;
while(!isInterrupted()) {
try {
if (mInputStream == null) return;
size = mInputStream.read(buffer);
if (size > 0) {
onDataReceived(buffer, size);
}
} catch (IOException e) {
e.printStackTrace();
return;
}
}
Log.d(TAG, "mReadThread quits while at" + System.currentTimeMillis());
}
}
在反復(fù)看這些文字后，我突然對(duì)“io阻塞”來(lái)了靈感，這才意識(shí)到，串口的InputStream.read()方法就是io操作呀，并且還會(huì)阻塞呀！
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.
即沒(méi)有字節(jié)就會(huì)一直block，有數(shù)據(jù)就會(huì)返回接收到的實(shí)際字節(jié)數(shù)量。
于是乎我茅塞頓開(kāi)：
1）接收線程之所于沒(méi)有及時(shí)退出，正是因?yàn)?code>SendingThread退出后，沒(méi)有字節(jié)流進(jìn)來(lái)，mReadThread就一直卡在read()方法，根本沒(méi)辦法去檢查isInterrupt().
2）串口雖然關(guān)閉，但是關(guān)閉串口前，接收線程就已經(jīng)運(yùn)行到了mInputStream.read(buffer)，并且阻塞在這，也就是說(shuō)接收通道一直存在，一旦有一個(gè)字符進(jìn)來(lái)，當(dāng)然是能讀到。
3）下一次啟動(dòng)活動(dòng)時(shí)打開(kāi)的SendgingThread發(fā)送的第一個(gè)字節(jié)就被這個(gè)mReadThread殘留的接收通道抓到了，然后它檢查while()條件發(fā)現(xiàn)isInterrupted()成立，這才退出歷史舞臺(tái)。后面的字節(jié)都被新活動(dòng)的mReadThread正常獲取。所以后面再在onDataReceived()中暫停就發(fā)現(xiàn)activity和SendingThread的activity一樣了。
4）有時(shí)候又可以正常退出的原因是，SendingThread在sleep()時(shí)拋出InterruptException清除了interrupt標(biāo)志，因此并沒(méi)有立即退出while循環(huán)，繼續(xù)發(fā)出一個(gè)字符，此時(shí)串口還沒(méi)來(lái)得及關(guān)閉，接收線程在收到這個(gè)字節(jié)后檢查while(!isInterrupted())不滿足，就迅速退出run()了。
解決辦法
給read()方法加上超時(shí)設(shè)置。需要修改linux底層串口終端配置，在SerialPort.c里添加以下代碼：
// 設(shè)置read超時(shí)
LOGD("before set, vtime is %d", cfg.c_cc[VTIME]);
LOGD("before set, vmin is %d", cfg.c_cc[VMIN]);
cfg.c_cc[VTIME] = 10;
cfg.c_cc[VMIN] = 0;
LOGD("after set, vtime is %d", cfg.c_cc[VTIME]);
LOGD("after set, vmin is %d", cfg.c_cc[VMIN]);
關(guān)于VTIME和VMIN的說(shuō)明參考這篇博文 [Linux串口中的超時(shí)設(shè)置]
設(shè)置前，通過(guò)log打印得知原來(lái)的VTIME為0，VMIN為1，即至少讀到1個(gè)字節(jié)才會(huì)返回否則一直阻塞。
現(xiàn)在我們來(lái)檢驗(yàn)一下增加超時(shí)后的效果，通過(guò)log打印信息還可以順便分析未設(shè)置超時(shí)時(shí)出錯(cuò)的具體過(guò)程：
完整LoopBackActivity代碼如下：
LoopBackActivity.java
public class LoopBackActivity extends SerialPortActivity {
private static final String TAG = "LoopBackActivity";
volatile byte mValueToSend;
volatile boolean mByteReceivedBack;
final Object mByteReceivedBackSemaphore = new Object();
volatile Integer mInComing = new Integer(0);
volatile Integer mOutGoing = new Integer(0);
volatile Integer mLost = new Integer(0);
volatile Integer mCorrupted = new Integer(0);
private SendingThread mSendingThread;
TextView mValueSentText;
TextView mInComingText;
TextView mOutGoingText;
TextView mLostText;
TextView mCorruptedText;
class SendingThread extends Thread {
@Override
public void run() {
while (!isInterrupted()) {
synchronized (mByteReceivedBackSemaphore) {
try {
Thread.sleep(100);
} catch (InterruptedException e) {
Log.d(TAG, "run: SendingThread is interrupted at " + System.currentTimeMillis());
}
mByteReceivedBack = false; // clear flag before sending
if (mOutputStream != null) {
try {
mOutputStream.write(mValueToSend);
} catch (IOException e) {
e.printStackTrace();
return;
}
} else return;
mOutGoing++;
Log.d(TAG, Thread.currentThread().getName() + " has sent " + mValueToSend
+ " at " + System.currentTimeMillis());
try {
mByteReceivedBackSemaphore.wait(100);
} catch (InterruptedException e) {}
Log.d(TAG, Thread.currentThread().getName() + " resumes at " + System.currentTimeMillis());
if (mByteReceivedBack == true) { // send success
mInComing++;
} else {
mLost++;
}
// show results on UI
runOnUiThread(new Runnable() {
@Override
public void run() {
mValueSentText.setText(String.valueOf(mValueToSend));
mInComingText.setText(String.format(Locale.getDefault(),"%d",mInComing));
mOutGoingText.setText(String.format(Locale.getDefault(),"%d",mOutGoing));
mLostText.setText(String.format(Locale.getDefault(),"%d",mLost));
mCorruptedText.setText(String.format(Locale.getDefault(),"%d",mCorrupted));
}
});
}
}
}
}
@Override
protected void onDataReceived(byte[] buffer, int size) {
synchronized (mByteReceivedBackSemaphore) {
for (int i = 0; i < size; i++) {
if (buffer[i] == mValueToSend && mByteReceivedBack == false) {
mValueToSend++;
mByteReceivedBack = true;
mByteReceivedBackSemaphore.notify();
Log.d(TAG, Thread.currentThread().getName() + " has notified at " + System.currentTimeMillis());
} else {
mCorrupted++;
}
}
}
}
@Override
protected void onCreate(Bundle savedInstanceState) {
mValueToSend = 0;
super.onCreate(savedInstanceState);
setContentView(R.layout.activity_loop_back);
mInComingText = (TextView)findViewById(R.id.TextViewIncomingValue);
mOutGoingText = (TextView)findViewById(R.id.TextViewOutgoingValue);
mLostText = (TextView)findViewById(R.id.TextViewLostValue);
mCorruptedText = (TextView)findViewById(R.id.TextViewCorruptedValue);
mValueSentText = (TextView)findViewById(R.id.TextViewCurrValueSent);
mSendingThread = new SendingThread();
mSendingThread.start();
}
@Override
protected void onDestroy() {
if (mSendingThread != null) {
mSendingThread.interrupt();
}
super.onDestroy();
}
}
SerialPortActivity.java
public abstract class SerialPortActivity extends AppCompatActivity {
private static final String TAG = "SerialPortActivity";
protected Application mApplication;
protected SerialPort mSerialPort;
protected OutputStream mOutputStream;
private InputStream mInputStream;
private ReadThread mReadThread;
private class ReadThread extends Thread {
@Override
public void run() {
super.run();
byte[] buffer = new byte[64];
int size;
while(!isInterrupted()) {
try {
if (mInputStream == null) return;
size = mInputStream.read(buffer);
if (size > 0) {
onDataReceived(buffer, size);
}
} catch (IOException e) {
e.printStackTrace();
return;
}
}
Log.d(TAG, "mReadThread quits while at" + System.currentTimeMillis());
}
}
@Override
protected void onCreate(Bundle savedInstanceState) {
super.onCreate(savedInstanceState);
mApplication = (Application)getApplication();
try {
mSerialPort = mApplication.getSerialPort();
mOutputStream = mSerialPort.getOutputStream();
mInputStream = mSerialPort.getInputStream();
/* Create a receiving thread */
mReadThread = new ReadThread();
mReadThread.start();
} catch (SecurityException e) {
DisplayError(R.string.error_security);
} catch (InvalidParameterException e) {
DisplayError(R.string.error_configuration);
} catch (IOException e) {
DisplayError(R.string.error_unknown);
}
}
private void DisplayError (int resourceID) {
AlertDialog.Builder b = new AlertDialog.Builder (this);
b.setTitle("Error");
b.setMessage(resourceID);
b.setPositiveButton("OK", new DialogInterface.OnClickListener() {
@Override
public void onClick(DialogInterface dialog, int which) {
SerialPortActivity.this.finish();
}
});
b.show();
}
protected abstract void onDataReceived(byte[] buffer, int size);
@Override
protected void onDestroy() {
if (mReadThread != null) {
mReadThread.interrupt();
Log.d(TAG, "onDestroy: mReadThread.interrupt() is called at " + System.currentTimeMillis());
}
mApplication.closeSerialPort();
Log.d(TAG, "onDestroy: SerialPort is closed at " + System.currentTimeMillis());
mSerialPort = null;
super.onDestroy();
}
}
不設(shè)置read()超時(shí)，即VTIME=0, VMIN=1時(shí)
-
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)
活動(dòng)銷(xiāo)毀時(shí)， 主線程中mReadThread.interrupt()先被調(diào)用，然后sleep中的SendingThread被interrupted后有幸發(fā)出最后一個(gè)字節(jié)"23"，mReadThread迅速捕捉到這個(gè)字節(jié)，發(fā)現(xiàn)自己中斷標(biāo)志置位，于是結(jié)束運(yùn)行，最后串口才被關(guān)閉，SendingThread試圖再次發(fā)送字節(jié)發(fā)生write異常然后結(jié)束運(yùn)行。所以不會(huì)產(chǎn)生任何歷史遺留問(wèn)題。
- 再看mReadThread沒(méi)能及時(shí)結(jié)束的情況
-- 異常退出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
活動(dòng)銷(xiāo)毀時(shí)，sleep中的SendingThread(Thread-331)首先被interrupted后發(fā)出最后一個(gè)字節(jié)，mReadThread（Thread-330)迅速捕捉到這個(gè)字節(jié)，可惜此后它的中斷標(biāo)志才被置位，也就是說(shuō)在中斷標(biāo)志置位前，它已經(jīng)卡在read()了，直到新的SendingThread(Thread-333)發(fā)出第一個(gè)字節(jié)后，mReadThread（Thread-330)才能結(jié)束運(yùn)行，此后新的mReadThread(Thread-332)才能接收到重發(fā)的第一個(gè)字節(jié)以及后面的字節(jié)。
異常退出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
活動(dòng)銷(xiāo)毀時(shí)， 主線程中mReadThread.interrupt()先被調(diào)用，然后sleep中的SendingThread被interrupted，還沒(méi)來(lái)得及發(fā)出下一個(gè)字節(jié)，串口就先關(guān)閉了，mReadThread等不來(lái)這個(gè)字節(jié)，只能卡在read()了，等待新的SendingThread來(lái)拯救它。
異常退出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
活動(dòng)銷(xiāo)毀時(shí)， 主線程中mReadThread.interrupt()先被調(diào)用，緊接著串口就被關(guān)閉，然后SendingThread才緩緩醒來(lái)，當(dāng)然無(wú)法發(fā)出字節(jié)了，mReadThread等不來(lái)這個(gè)字節(jié)，只能卡在read()了，等待新的SendingThread來(lái)拯救它。
可見(jiàn)，異常退出的情況有很多種，都是不能同時(shí)滿足“中斷標(biāo)志先置位然后收到一個(gè)字節(jié)退出read()阻塞狀態(tài)”這兩個(gè)條件，這是由于多線程并發(fā)運(yùn)行的隨機(jī)性造成的，不打印出來(lái)還真不知道原來(lái)多線程并發(fā)運(yùn)行時(shí)這么“隨意”哈。
- 那么設(shè)置了超時(shí)后帶來(lái)的效果，VTIME=10, VMIN=0, 即超時(shí)10*100ms后read()返回
先看mReadThread正常結(jié)束時(shí)，和不加超時(shí)設(shè)置時(shí)一樣，超時(shí)還沒(méi)發(fā)揮出它的威力：
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沒(méi)能及時(shí)結(jié)束的情況
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
活動(dòng)銷(xiāo)毀時(shí)， 主線程中mReadThread.interrupt()先被調(diào)用，緊接著串口就被關(guān)閉，然后SendingThread才緩緩醒來(lái)，當(dāng)然無(wú)法發(fā)出字節(jié)了，mReadThread等不來(lái)這個(gè)字節(jié)，卡在read()，然而這回沒(méi)有一直傻等下去，在等了1000ms左右后從read()超時(shí)返回，結(jié)束運(yùn)行。（實(shí)測(cè)超時(shí)后，mInputStream.read(buffer)返回-1，說(shuō)明串口設(shè)備的InputStream在超時(shí)后會(huì)認(rèn)為達(dá)到流末尾）
增加超時(shí)后，間隔2秒以上（因?yàn)槎〞r(shí)沒(méi)那么準(zhǔn)確）看到"quits while"后再重啟活動(dòng)，就絕對(duì)不會(huì)出現(xiàn)第一個(gè)字節(jié)“l(fā)ost”了，但是間隔短于2秒的操作還是有可能"lost"第一個(gè)字節(jié)，不能接受的話，就把超時(shí)時(shí)間再設(shè)置的短一些吧。
