使用 Serial Port 來除錯的時候請小心

一般來說，程式設計師在除錯的時候常常會用的一種方式就是 print 大法，在程式適當的地方插入一些顯示資訊的指令，提供開發者更多資料來除錯。而在使用這個方法來除錯的時候，有很高的機會是利用 serial port 來顯示信息，特別是在嵌入式系統的開發上。然而當透過 serial port 來印信息的時候有著潛在的風險，因為在工作上遇到了，所以就特別紀錄在下面。首先先來看看下面這一段程式。

1
2
3
4
5
6
7
#!/usr/bin/python

import sys
import time

for item in range( 0, 10000, 1 ):
    print str( item ) + " ABCDEFGHIJKLMNOPQRSTUVWXYZABCDEFGHIJKLMNOPQRSTUVWXYZABCDEFGHIJKLMNOPQRSTUVWXYZ"


這段程式相當的簡單，就只是單純的把一個字串印個 10000 次罷了。然後我們分別透過 SSH 以及 Serial port 連到測試設備上執行這個程式，並利用 time 這個指令來量測時間。結果記錄在下面(省略印字串的輸出)。

SSH:
root@OpenWrt:~# time ./test_print_01.py
real    0m 0.68s
user    0m 0.18s
sys     0m 0.08s

Serial Port (115200):
root@OpenWrt:~# time ./test_print_01.py
real    1m 8.18s
user    0m 0.17s
sys     0m 0.07s

可以發現時間差距非常的多，理由很簡單，因為 serial port 的輸出速度只有 115200 bps(本篇的實驗設備)，所以慢也很正常的。問題是，如果今天要除錯的程式是一隻 time critical 的程式，那這就會遇到很大的麻煩。先把程式列在下面：

test_print.py 

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
#!/usr/bin/python

import sys
import time
import threading
from socket import *

BUFSIZE = 1024

class myThread (threading.Thread):
    def __init__( self, threadID, name, port ):
        threading.Thread.__init__(self)
        self.threadID = threadID
        self.name = name
        self.port = port
    def run(self):
        print "Start UDP server: " + self.name + " (" + str( self.port ) + ")"
        s = socket( AF_INET, SOCK_DGRAM )
        s.bind( ( '', self.port ) )
        while 1:
            data, addr = s.recvfrom( BUFSIZE )
            print 'server received %r from %r' % (data, addr)
            s.sendto( data, addr )
        print "Exiting " + self.name

thread1 = myThread( 1, "Thread-1", 20000 )

thread1.start()

for item in range( 0, 500000, 1 ):
    print str( item ) + " ABCDEFGHIJKLMNOPQRSTUVWXYZABCDEFGHIJKLMNOPQRSTUVWXYZABCDEFGHIJKLMNOPQRSTUVWXYZ"

test_print_client.py

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
#!/usr/bin/python

import sys
import time
import datetime
from socket import *

BUFSIZE = 1024

addr = "127.0.0.1", 20000
s = socket(AF_INET, SOCK_DGRAM)
s.bind( ( '', 0 ) )

for item in range( 0, 100000, 1 ):
    time1 = datetime.datetime.now()
    print "[", time1, "]: Send"
    s.sendto( "++++++++++", addr )
    data, fromaddr = s.recvfrom( BUFSIZE )
    time2 = datetime.datetime.now()
    print "[", time2, "]: Recv %r from %r" % ( data, fromaddr )
    elapsedTime = time2 - time1
    print "Time Diff:", elapsedTime
    time.sleep(2)

上面這隻程式很簡單，說穿了就是開了一個 thread 來做 echo server，同時在 main thread 中拼命的印東西。另外一隻程式則是簡單的 echo client。接下來我們讓 test_print.py 分別在 SSH 以及 Serial Port 上面執行，client 的部分則統一在 SSH 上面執行，來看看會有甚麼差別。

SSH:
root@OpenWrt:~# ./test_print_client.py
[ 2017-04-17 13:55:14.600182 ]: Send
[ 2017-04-17 13:55:14.796277 ]: Recv '++++++++++' from ('127.0.0.1', 20000)
Time Diff: 0:00:00.196095
[ 2017-04-17 13:55:16.798956 ]: Send
[ 2017-04-17 13:55:16.842231 ]: Recv '++++++++++' from ('127.0.0.1', 20000)
Time Diff: 0:00:00.043275
[ 2017-04-17 13:55:18.844467 ]: Send
[ 2017-04-17 13:55:18.913060 ]: Recv '++++++++++' from ('127.0.0.1', 20000)
Time Diff: 0:00:00.068593
[ 2017-04-17 13:55:20.915303 ]: Send
[ 2017-04-17 13:55:20.922704 ]: Recv '++++++++++' from ('127.0.0.1', 20000)
Time Diff: 0:00:00.007401
[ 2017-04-17 13:55:22.924940 ]: Send
[ 2017-04-17 13:55:22.951737 ]: Recv '++++++++++' from ('127.0.0.1', 20000)
Time Diff: 0:00:00.026797

Serial Port:
root@OpenWrt:~# ./test_print_client.py
[ 2017-04-17 13:57:37.278359 ]: Send
[ 2017-04-17 13:57:39.991233 ]: Recv '++++++++++' from ('127.0.0.1', 20000)
Time Diff: 0:00:02.712874
[ 2017-04-17 13:57:41.993506 ]: Send
[ 2017-04-17 13:57:45.668543 ]: Recv '++++++++++' from ('127.0.0.1', 20000)
Time Diff: 0:00:03.675037
[ 2017-04-17 13:57:47.670792 ]: Send
[ 2017-04-17 13:57:51.346018 ]: Recv '++++++++++' from ('127.0.0.1', 20000)
Time Diff: 0:00:03.675226
[ 2017-04-17 13:57:53.346490 ]: Send
[ 2017-04-17 13:57:57.023386 ]: Recv '++++++++++' from ('127.0.0.1', 20000)
Time Diff: 0:00:03.676896
[ 2017-04-17 13:57:59.025634 ]: Send
[ 2017-04-17 13:58:02.700888 ]: Recv '++++++++++' from ('127.0.0.1', 20000)
Time Diff: 0:00:03.675254

 可以看到 Serial Port 所需要的時間是 SSH 的數十倍。明明是同樣的程式，只是因為輸出界面的差異就可以在效能上有如此大的區別，所以在使用 print 大法的時候實在是應該要小心。

當然，剛剛那隻程式的 print 實在是太暴力了，我們稍微改寫一下：

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
#!/usr/bin/python

import sys
import time
import threading
from socket import *

BUFSIZE = 1024

class myThread (threading.Thread):
    def __init__( self, threadID, name, port ):
        threading.Thread.__init__(self)
        self.threadID = threadID
        self.name = name
        self.port = port
    def run(self):
        print "Start UDP server: " + self.name + " (" + str( self.port ) + ")"
        s = socket( AF_INET, SOCK_DGRAM )
        s.bind( ( '', self.port ) )
        while 1:
            data, addr = s.recvfrom( BUFSIZE )
            print 'server received %r from %r' % (data, addr)
            s.sendto( data, addr )
        print "Exiting " + self.name

thread1 = myThread( 1, "Thread-1", 20000 )

thread1.start()

for item in range( 0, 500000, 1 ):
    print str( item ) + " ABCDEFGHIJKLMNOPQRSTUVWXYZABCDEFGHIJKLMNOPQRSTUVWXYZABCDEFGHIJKLMNOPQRSTUVWXYZ"
    time.sleep(0.005)

其實只是加上了 sleep( 0.005 )。為什麼是 0.005 ... 因為在工作上列印了太多的 log ，平均起來一秒印了 200 行，所以就先設定為 0.005 囉。結果如下：

SSH:
root@OpenWrt:~# ./test_print_client.py
[ 2017-04-17 14:10:51.235181 ]: Send
[ 2017-04-17 14:10:51.236046 ]: Recv '++++++++++' from ('127.0.0.1', 20000)
Time Diff: 0:00:00.000865
[ 2017-04-17 14:10:53.236485 ]: Send
[ 2017-04-17 14:10:53.237083 ]: Recv '++++++++++' from ('127.0.0.1', 20000)
Time Diff: 0:00:00.000598
[ 2017-04-17 14:10:55.239284 ]: Send
[ 2017-04-17 14:10:55.239859 ]: Recv '++++++++++' from ('127.0.0.1', 20000)
Time Diff: 0:00:00.000575
[ 2017-04-17 14:10:57.242061 ]: Send
[ 2017-04-17 14:10:57.242655 ]: Recv '++++++++++' from ('127.0.0.1', 20000)
Time Diff: 0:00:00.000594
[ 2017-04-17 14:10:59.244856 ]: Send
[ 2017-04-17 14:10:59.245456 ]: Recv '++++++++++' from ('127.0.0.1', 20000)
Time Diff: 0:00:00.000600
[ 2017-04-17 14:11:01.246487 ]: Send
[ 2017-04-17 14:11:01.247073 ]: Recv '++++++++++' from ('127.0.0.1', 20000)
Time Diff: 0:00:00.000586
[ 2017-04-17 14:11:03.249279 ]: Send
[ 2017-04-17 14:11:03.249872 ]: Recv '++++++++++' from ('127.0.0.1', 20000)
Time Diff: 0:00:00.000593
[ 2017-04-17 14:11:05.252072 ]: Send
[ 2017-04-17 14:11:05.252653 ]: Recv '++++++++++' from ('127.0.0.1', 20000)
Time Diff: 0:00:00.000581
[ 2017-04-17 14:11:07.254854 ]: Send
[ 2017-04-17 14:11:07.255434 ]: Recv '++++++++++' from ('127.0.0.1', 20000)
Time Diff: 0:00:00.000580
[ 2017-04-17 14:11:09.256489 ]: Send
[ 2017-04-17 14:11:09.257069 ]: Recv '++++++++++' from ('127.0.0.1', 20000)
Time Diff: 0:00:00.000580
[ 2017-04-17 14:11:11.259268 ]: Send
[ 2017-04-17 14:11:11.259870 ]: Recv '++++++++++' from ('127.0.0.1', 20000)
Time Diff: 0:00:00.000602
[ 2017-04-17 14:11:13.262075 ]: Send
[ 2017-04-17 14:11:13.262657 ]: Recv '++++++++++' from ('127.0.0.1', 20000)
Time Diff: 0:00:00.000582
[ 2017-04-17 14:11:15.264855 ]: Send
[ 2017-04-17 14:11:15.265425 ]: Recv '++++++++++' from ('127.0.0.1', 20000)
Time Diff: 0:00:00.000570
[ 2017-04-17 14:11:17.266485 ]: Send
[ 2017-04-17 14:11:17.267076 ]: Recv '++++++++++' from ('127.0.0.1', 20000)
Time Diff: 0:00:00.000591
[ 2017-04-17 14:11:19.269279 ]: Send
[ 2017-04-17 14:11:19.269852 ]: Recv '++++++++++' from ('127.0.0.1', 20000)
Time Diff: 0:00:00.000573
[ 2017-04-17 14:11:21.272052 ]: Send
[ 2017-04-17 14:11:21.272616 ]: Recv '++++++++++' from ('127.0.0.1', 20000)
Time Diff: 0:00:00.000564

Serial Port:
root@OpenWrt:~# ./test_print_client.py
[ 2017-04-17 14:08:34.943589 ]: Send
[ 2017-04-17 14:08:34.944421 ]: Recv '++++++++++' from ('127.0.0.1', 20000)
Time Diff: 0:00:00.000832
[ 2017-04-17 14:08:36.946486 ]: Send
[ 2017-04-17 14:08:36.947092 ]: Recv '++++++++++' from ('127.0.0.1', 20000)
Time Diff: 0:00:00.000606
[ 2017-04-17 14:08:38.949301 ]: Send
[ 2017-04-17 14:08:38.949905 ]: Recv '++++++++++' from ('127.0.0.1', 20000)
Time Diff: 0:00:00.000604
[ 2017-04-17 14:08:40.952110 ]: Send
[ 2017-04-17 14:08:40.952706 ]: Recv '++++++++++' from ('127.0.0.1', 20000)
Time Diff: 0:00:00.000596
[ 2017-04-17 14:08:42.954913 ]: Send
[ 2017-04-17 14:08:42.955494 ]: Recv '++++++++++' from ('127.0.0.1', 20000)
Time Diff: 0:00:00.000581
[ 2017-04-17 14:08:44.956492 ]: Send
[ 2017-04-17 14:08:50.240876 ]: Recv '++++++++++' from ('127.0.0.1', 20000)
Time Diff: 0:00:05.284384
[ 2017-04-17 14:08:52.243117 ]: Send
[ 2017-04-17 14:08:52.243708 ]: Recv '++++++++++' from ('127.0.0.1', 20000)
Time Diff: 0:00:00.000591
[ 2017-04-17 14:08:54.245913 ]: Send
[ 2017-04-17 14:08:54.246531 ]: Recv '++++++++++' from ('127.0.0.1', 20000)
Time Diff: 0:00:00.000618
[ 2017-04-17 14:08:56.248738 ]: Send
[ 2017-04-17 14:08:56.249326 ]: Recv '++++++++++' from ('127.0.0.1', 20000)
Time Diff: 0:00:00.000588
[ 2017-04-17 14:08:58.251531 ]: Send
[ 2017-04-17 14:08:58.252116 ]: Recv '++++++++++' from ('127.0.0.1', 20000)
Time Diff: 0:00:00.000585
[ 2017-04-17 14:09:00.254326 ]: Send
[ 2017-04-17 14:09:00.254899 ]: Recv '++++++++++' from ('127.0.0.1', 20000)
Time Diff: 0:00:00.000573
[ 2017-04-17 14:09:02.256485 ]: Send
[ 2017-04-17 14:09:02.257076 ]: Recv '++++++++++' from ('127.0.0.1', 20000)
Time Diff: 0:00:00.000591
[ 2017-04-17 14:09:04.259290 ]: Send
[ 2017-04-17 14:09:08.467511 ]: Recv '++++++++++' from ('127.0.0.1', 20000)
Time Diff: 0:00:04.208221
[ 2017-04-17 14:09:10.468712 ]: Send
[ 2017-04-17 14:09:10.469497 ]: Recv '++++++++++' from ('127.0.0.1', 20000)
Time Diff: 0:00:00.000785
[ 2017-04-17 14:09:12.471345 ]: Send
[ 2017-04-17 14:09:12.472161 ]: Recv '++++++++++' from ('127.0.0.1', 20000)
Time Diff: 0:00:00.000816
[ 2017-04-17 14:09:14.473987 ]: Send
[ 2017-04-17 14:09:14.474775 ]: Recv '++++++++++' from ('127.0.0.1', 20000)
Time Diff: 0:00:00.000788

看起來結果差不多，不過 serial port 不定時會出現飆高的狀況。因此，在透過 Serial Port 使用 print 大法的時候，要記得這是會影響效能的。

PS. 在 python 上使用 threading 的話，使用了 Ctrl-C 來中止程式， thread 還是會繼續執行唷。 

留言

張貼留言

這個網誌中的熱門文章

我弟家的新居感恩禮拜分享：善頌善禱

語本禮記·檀弓下：「晉獻文子成室，晉大夫發焉。張老曰：『美哉輪焉！美哉奐焉！歌於斯，哭於斯，聚國族於斯。』文子曰：『武也，得歌於斯，哭於斯，聚國族於斯，是全要領以從先大夫於九京也。』北面再拜稽首。君子謂之：『善頌善禱』。」 不知為什麼，我一直對禮記中的這一篇印象深刻，大概是小時候記憶力比較好，所以一直刻劃在心中吧。之前有天我弟要我把時間留下來，要參加他們家的家庭禮拜，結果到了以後才發現原來是新居感恩禮拜（我說，你們小倆口根本已經搬進去很久了吧），然後居然還要說些祝福的話（喂喂，下次這種事要先講，我本來抱定只聽只吃不說話的態度啊），在想要講什麼的時候，第一個浮出的念頭就是「善頌善禱」的這個故事 ... ㄜ ... 不是聖經經文啊，所以就想找找，在聖經中哪一段有「新居落成」的相關經節，可以作為分享，結果就是以下面這段文章來做分享： 王上9：1-10 所羅門建造耶和華殿和王宮，並一切所願意建造的都完畢了，耶和華就二次向所羅門顯現，如先前在基遍向他顯現一樣，對他說：「你向我所禱告祈求的，我都應允了。我已將你所建的這殿分別為聖，使我的名永遠在其中；我的眼、我的心也必常在那裡。你若效法你父大衛，存誠實正直的心行在我面前，遵行我一切所吩咐你的，謹守我的律例典章，我就必堅固你的國位在以色列中，直到永遠，正如我應許你父大衛說：你的子孫必不斷人坐以色列的國位。倘若你們和你們的子孫轉去不跟從我，不守我指示你們的誡命律例，去事奉敬拜別神，我就必將以色列人從我賜給他們的地上剪除，並且我為己名所分別為聖的殿也必捨棄不顧，使以色列人在萬民中作笑談，被譏誚。這殿雖然甚高，將來經過的人必驚訝、嗤笑，說：耶和華為何向這地和這殿如此行呢？人必回答說：是因此地的人離棄領他們列祖出埃及地之耶和華─他們的神，去親近別神，事奉敬拜他，所以耶和華使這一切災禍臨到他們。」所羅門建造耶和華殿和王宮，這兩所二十年才完畢了。 在列王記上的記載裏面，所羅門花了二十年的時間完成了聖殿和皇宮的建造，而現在上帝來參加這個「新居感恩禮拜」。上帝說：「 我已將你所建的這殿分別為聖，使我的名永遠在其中；我的眼、我的心也必常在那裡。 」感謝上帝，這是上帝同在的保證，這是基督徒最喜歡傳講平安的福音：「以馬內利，上帝與我們同在」，以上帝給的祝福來說，沒有比這更大的。可是等等，接下來的話是新居落成時所該給的祝福嗎？一開始還好，可
閱讀完整內容

如何將Linux打造成OpenFlow Switch：Openvswitch

圖片
因為工作上被指派去做SDN，自然需要SDN的網路設備才可以。問題是SDN Switch賣的超級貴的，一台差不多要30萬台幣。這跟當初推廣SDN的人說法完全不一樣！他們當初說SDN網路設備會變得比較便宜，因為網路設備上不需要在堆疊這麼多的網路協定，因此硬體可以Cost Down，也可以省下軟體的錢。問題是，如果單單賣純種SDN Switch根本是不可能的事情啊，因為缺少可以在上面跑的軟體和控制器，所以只好保留傳統設備上的功能，再多加OpenFlow的支援，並提供給使用者選擇的開關。這樣當然只會更貴不會便宜啊！！ 在沒錢、沒人、沒資源的情況下，要怎麼辦呢？用模擬軟體？可惜要Demo的時候行不通。那就只好自己來打造一台SDN Switch了。雖然沒有晶片的支援，但只要不牽扯到效能的話，應該沒太多問題。下面是我和同事想過的一些解決方案： 自己打造OpenFlow的Agent，反正OpenFlow的網路協定並不複雜，然後透過Linux Kernel的netfilter來模擬晶片的行為。因為是用軟體模擬，所以效率會比較差，但反過來說，因為是軟體，所以我可以滿足所有OpenFlow的要求，不會有做不到的事情。不過這個提案被一個PM的同事封殺了，理由是這不能賣錢 ...  有一個同事找到一個有趣的專案 FlowForwarding 。這個專案提供了Open Source的OpenFlow Agent: LINC。LINC是用Erlang所開發的軟體。雖然我根本不會Erlang，但程式語言不是我考慮的重點，我好奇的是它要怎麼模擬晶片來處理封包。從網頁上看到，LINC在使用上需要libpcap的函式庫，初步猜測，LINC應該是把所有的封包透過libpcap攔截到user space以後進行修改。這樣做的效率應該會比我的解決方案更差。 OpenVswitch 。這是大部份產品的解決方案。我聽過一堆公司宣稱自己有了SDN Switch，而內容只不過是把Openvswitch移植到自己原有的產品上罷了。一樣，我好奇它要怎麼模擬晶片來處理封包，看了編譯過程，它會產生openvswitch.ko，在加上它利用bridge的特性，所以應該是在linux bridge那邊進行hook後修改。 考量到移植的方便性，所以後來我個人選擇openvswitch作為SDN Switch的解決方
閱讀完整內容

Openssl 範例程式：建立SSL連線

說來很神奇，雖然我研究所的研究主題是「網路安全」，但我在研究所卻從來沒撰寫使用 openssl 函式庫的程式。第一次撰寫是在工作上有需求而去使用一些加密的演算法，這次則是工作尚有需求，要去建立 DTLS 的安全連線。DTLS？等一下，標題不是 SSL 嗎？說來話長，要使用 DTLS 的相關 API，按照 openssl 網站的說法，最好是使用 openssl 1.0 以後的版本，問題是客戶所使用的版本是 0.9.8d 的。理論上來說，0.9.8d 的版本也有支援 DTLS，所以我不能拒絕客戶的要求（我會努力繼續嘗試說服客戶的），但還是要做好在 0.9.8d 的開發。問題是兩個版本的寫法不一樣啊（在 1.0.0 以後的版本，有一個 dtlsv1_listen 的函式，簡單來說就是在 UDP 上面實作 listen 的行為。）~雖然已經請同事搞定 1.0 上面的寫法，但 0.9.8 上的寫法還要再研究。所以我就進去開始研究囉。下面就是研究到一半（SSL）的心得。下面的程式碼是從 HP 的網站上改過來的。 ssl_server.c # include < stdio.h > # include < stdlib.h > # include < string.h > # include < errno.h > # include < netdb.h > # include < unistd.h > # include < sys/types.h > # include < sys/socket.h > # include < netinet/in.h > # include < arpa/inet.h > # include < openssl/crypto.h > # include < openssl/ssl.h > # include < openssl/err.h > # define RSA_SERVER_CERT " serverca.crt " # define RSA_SERVER_KEY " serve
閱讀完整內容