2014-10-04 38 views
1

花了不正確的時間當我做 - $ time curl 'http://localhost:3000'
我得到這個:0.00s user 0.00s system 0% cpu 1.270 total
創業板架小型分析器「還顯示拍攝時間爲捲曲幾乎相同。Rails的顯示要求

但在Rails日誌,我見式
Completed 200 OK in 103ms (Views: 72.7ms | ActiveRecord: 5.0ms)

爲什麼有大約1秒的時間差?

Curl和rails服務器都在我的開發機器上運行。

回答

0

「時間捲曲」是計時curl客戶端獲取Rails內容所花費的時間,即它是客戶端時間。

Rails日誌顯示了服務器時間。

+0

我看着它,gem'rack-mini-profiler'也顯示時間幾乎與捲曲相同。 – 2014-10-04 13:26:29

+0

我認爲,導軌有些不正確。 – 2014-10-04 13:27:49

+0

不知道爲什麼。在日誌輸出發生後,可能會插入其他Rack中間件,即第三方gem。小型剖析器可能有助於診斷它。 – mahemoff 2014-10-04 13:32:30

0

您沒有指定,但是如果您正在運行開發模式,則存在類重新加載和資產編譯,這會嚴重影響響應時間。但它不影響生產。

以下是我在軌得到了4.2的應用程序(第一卷曲,比相應的日誌摘錄):

curl 'http://localhost:3000' 0.01s user 0.00s system 0% cpu 1.817 total 
curl 'http://localhost:3000' 0.01s user 0.00s system 2% cpu 0.366 total 


Completed 200 OK in 1254ms (Views: 1206.2ms | ActiveRecord: 13.9ms) 
127.0.0.1 - - [04/Oct/2014:19:48:52 +0200] "GET/HTTP/1.1" 200 - 1.6863 

Completed 200 OK in 279ms (Views: 278.7ms | ActiveRecord: 0.0ms) 
127.0.0.1 - - [04/Oct/2014:19:49:41 +0200] "GET/HTTP/1.1" 200 - 0.2895 

雖然在製作:

curl 'http://localhost:3000' 0.01s user 0.00s system 3% cpu 0.329 total 
curl 'http://localhost:3000' 0.00s user 0.01s system 11% cpu 0.090 total 

I, [2014-10-04T19:54:02.739988 #27830] INFO -- : Completed 200 OK in 143ms (Views: 123.0ms | ActiveRecord: 6.3ms) 
I, [2014-10-04T19:54:17.521175 #27830] INFO -- : Completed 200 OK in 41ms (Views: 40.9ms | ActiveRecord: 0.0ms) 

所以仍有差異存在,但它是可能是由於curl發送請求到服務器,然後收到響應的時間。我仍然認爲重新加載和編譯會導致更大的開發差異。

+0

在軌道日誌中顯示的請求沒有花費時間包括資產編譯和類重新加載? – 2014-10-04 17:05:51

+0

這只是我的猜測,但它不會計算類重新加載來請求時間。我更深入地編輯了我的答案。 – katafrakt 2014-10-04 17:58:28