使用 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 還是會繼續執行唷。 

留言

張貼留言

這個網誌中的熱門文章

如何將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...
閱讀完整內容

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

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

Linux Virtual Interface: TUN/TAP

圖片
今天要介紹的，不是什麼新技術，只是之前沒碰過，而現在工作有用到，所以做個私人紀錄。 問題描述以及過去的解決方案 工作上面遇到的問題，如何建立一張虛擬的網路介面，並且讓封包經過該介面後額外封裝一個新的 Header。建立虛擬網路介面不難，但要如何去撈封包（使封包經過該介面）呢？並且之後封包的處理又是如何？之前在公司曾經用過幾種招數： 第一個作法是透過 Bridge 來將網卡綁在一起，然後去修改 Bridge 的程式碼做自己想做的事情。第二個作法是透過 Netfilter 來攔截封包，做完事情以後再硬導到正確的網卡。這兩個作法很 亂來 ，我的亂來指的是不理會 Linux 內部封包處理流程，隨意的處理並安插封包，但我可沒說這樣做不到啊。第3種方法很好，完全符合 Linux 核心的封包處理程序，代表的例子就是 GRE，問題是現在的封裝技術亂七八糟（這個詞純粹是為了抱怨用），並不一定是單純的 IP-in-IP ，所以這個架構不一定適用。正當決定來亂搞的時候，有人提供了一個新的方向（應該是說自己孤陋寡聞）：TUN/TAP。 TUN/TAP: Virtual Network Kernel Device 我們先抄一下 Wiki 上的說明： In computer networking, TUN and TAP are virtual-network kernel devices . Being network devices supported entirely in software, they differ from ordinary network devices which are backed up by hardware network adapters. TUN (namely network TUNnel) simulates a network layer device and it operates with layer 3 packets like IP packets . TAP (namely network tap) simulates a link layer device and it operates with layer 2 packets like Ethernet frames . TUN is used...
閱讀完整內容