1. 程式人生 > >日誌中每段程式碼執行時間的和不等於整段程式碼執行的總時間

日誌中每段程式碼執行時間的和不等於整段程式碼執行的總時間

程式碼邏輯:

def  getInlink()

     A  -> B  -> C ->  D

 

在tornado中呼叫getInlink

@tornado.gen.coroutine

    def get(self):

        start2 = int(time.time()*1000)

        error, errReason, lstSummary = yield self.getInlink(utfQuery)

        print 'total use %d' % (int(time.time()*1000)-start2)

實踐中,分別記錄了上面四個步驟執行的時間, 假設為At, Bt, Ct, Dt,並且記錄了getInlink總的時間,假設為ADt(呼叫getInlink方法到返回的時間)

發現4個程式碼片段的時間的和不等於總的時間, 也就是:

        ADt >  At+Bt+Ct+Dt

 

原因是什麼呢?

之前分析過的錯誤的原因:

         A->D這個步驟中應該還有CPU排程的等待時間,這段程式碼並不是一直都在執行

        尤其,這4步如果有IO的話,假設B中有IO,那麼在B執行IO的過程中,該程序會被掛起,而當IO執行完後,也不一定馬上就可以被CPU排程執行,很可能還要等待一段時間

 

正確的原因:

        其實上面分析的原因不對,因為B中的IO雖然會等待被排程,但是Bt的時間其實已經包含了那段等待被呼叫的時間了

        真實的原因應該是呼叫getInlink方法用了yield,所以它所在的get方法就變成了迭代器,這個方法需要等待被tornado的空閒的執行緒來呼叫,所以應該是:

         

   ADt =  At+Bt+Ct+Dt + getInlink方法等待被執行的時間