MicroProfile OpenTracing・哪邊有問題?

如果碰到系統運作不順暢,或者說有點慢,你們會怎麼做呢?
或許很多開發者會和我一樣選擇最簡單的方法 => 插個 旗子。大概的做法就是:

  1. 找到可能的問題邏輯
  2. 在執行前先取得系統時間,並印出一些訊息
  3. 在執行後取得系統時間,計算執行時長,再印出一些訊息

這是非常實用的技巧,在開發的前期階段經常會用到,可以幫助快速找出問題。

但隨著專案的演進,模組、系統逐漸長大,插旗雖然簡單,但似乎變得有點麻煩。手動一層一層插旗,再手動一層一層移除,持續考驗著開發者的耐性。隨著工具的演進,有了 Debugger 和 Profiler 這樣的工具可以使用,讓除錯變得簡單了一些,的確也幫開發者省了很多事。
無論插旗或者使用開發工具,目的都只有一個:「在程式邏輯結果無誤的情況下,找出運行不順暢的可能原因。」

以上所講的都是在開發階段,那到測試或生產環境時又該怎麼處理呢?

  • 插旗真好用 => 不管是直接印出或使用 Logger,不可避免的將面對龐大的資料量。此外,在不想損耗性能的情況下,怎麼設計可精準找到問題的旗子也是難題
  • Debugger 真好用 => 錯誤發生時,Debugger 肯定還沒開,等開好異常狀況也錯過了
  • Profiler 真好用 => Profiler 提供的是統計結果,換言之,若長期啟動,短暫的異常將被長期正常運作的數據給稀釋,反而會誤以為沒有問題

有時回頭想,從事系統開發真的好艱難啊......(遠目

MicroProfile 中的 MicroProfile OpenTracing(後簡稱 MPOpenTracing)就是要來協助解決以上問題。和其它規格相同,沒有必要不會重新造輪子,MPOpenTracing 就是採用了 OpenTracing 的規格,再額外加上了一些自動化與簡化,幫助開發者能更簡單的對系統進行追蹤。


如何啟動?

因為 MPOpenTracing 是個規格,各家的實作可能略有不同,又因為「追蹤」是需要使用資源的,所以它並沒有自動啟動,需要手動打開。以我使用的 PayaraMicro 為例,需要在啟動時加入參數 --enableRequestTracing

若你和我一樣是使用 maven 進行開發,可以在 pom.xml => payara-micro-maven-plugin => configuration => commandLineOptions 之中加入啟動參數,如下:

...
<plugin>
    <groupId>fish.payara.maven.plugins</groupId>
    <artifactId>payara-micro-maven-plugin</artifactId>
    ...
    <configuration>
        ...
        <commandLineOptions>
            ...
            <option>
                <key>--enableRequestTracing</key>
            </option>
        </commandLineOptions>
    </configuration>
</plugin>
...

PayaraMicro 預設是執行 30 秒以上的請求就會觸發 MPOpenTracing 的機制,完整參數設定說明請參考 Request Tracing in Payara Micro

就這樣,我們做好了使用 MPOpenTracing 的準備。

如何追蹤?

其實,可以什麼都不用做。
是的,你沒看錯,什麼都不用做,就可以自動追蹤了!但這是有前提的:

  1. 滿足被追蹤的條件。PayaraMicro 上預設請求執行超過 30 秒以上,就滿足了追蹤的條件。
  2. 追蹤的範圍是來自 JAX-RS 的請求,或者由開發者發出的 JAX-RS 請求。

簡單說,MPOpenTracing 會自動追蹤 JAX-RS 的進與出,而在 PayaraMicro 上,只有執行超過 30 秒的這些行為會留下追蹤紀錄。

太棒了!!!
微服務架構下重點就在服務的開發與整合,這部分的追蹤自動達成了,可以調整的執行時間門檻,能夠大幅減少所需關注的資訊量,避免被海量資訊淹沒,讓異常情況的浮現變得容易。

等等...... 那 JAX-RS 以外的怎麼辦?
很簡單,用個 @Traced 標註就搞定。請參考一下範例:

@Path("hello")
@ApplicationScoped
public class HelloOpenTracing {

    @Inject
    private MessageGenerator mg;

    @GET
    public String sayHello() throws InterruptedException {
        return mg.getMessage(30);
    }
}
@Traced
@Dependent
public class MessageGenerator {

    public String getMessage(long sleepSeconds) {
        try {
            TimeUnit.SECONDS.sleep(sleepSeconds);
        } catch (InterruptedException ex) {
        }
        return "Hello World!";
    }
}

範例很簡單,呼叫 MessageGeneratorgetMessage 時會睡 30 秒,達到觸發的條件。同時,MessageGenerator 上標記了 @Traced 讓整個 class 的 method 都可以被追蹤。

實際執行後,會在 console 看到以下類似的結果:

[2020-03-07T19:35:42.597+0800] [] [資訊] [] [fish.payara.nucleus.notification.log.LogNotifierService] [tid: _ThreadID=29 _ThreadName=http-thread-pool::http-listener(2)] [timeMillis: 1583580942597] [levelValue: 800] [[
  Request execution time: 30372(ms) exceeded the acceptable threshold - {"traceSpans":[
{"operationName":"processContainerRequest","spanContext":{"spanId":"d262cf8b-9fd4-42c4-bb14-b85464614d7c","traceId":"a1fe155e-eb45-4070-b29a-176ca4d40717"},"startTime":"2020-03-07T19:35:12.084300+08:00[Asia/Taipei]","endTime":"2020-03-07T19:35:42.456846+08:00[Asia/Taipei]","traceDuration":"30372546000","spanTags":[{"Server": "server"},{"Domain": "domain1"}]},
{"operationName":"processWebserviceRequest","spanContext":{"spanId":"9bc20e68-ca75-47c2-b03f-44ffa0ecdb64","traceId":"a1fe155e-eb45-4070-b29a-176ca4d40717"},"startTime":"2020-03-07T19:35:12.229490+08:00[Asia/Taipei]","endTime":"2020-03-07T19:35:42.447342+08:00[Asia/Taipei]","traceDuration":"30217839000","spanTags":[{"accept-language": "[zh-TW,en;q=0.5]"},{"ResponseStatus": "200"},{"host": "[localhost:8080]"},{"upgrade-insecure-requests": "[1]"},{"connection": "[keep-alive]"},{"Method": "GET"},{"URL": "http://localhost:8080/api/hello"},{"accept-encoding": "[gzip, deflate]"},{"user-agent": "[Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:73.0) Gecko/20100101 Firefox/73.0]"},{"accept": "[text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8]"}],"references":[{"spanContext":{"spanId":"d262cf8b-9fd4-42c4-bb14-b85464614d7c","traceId":"a1fe155e-eb45-4070-b29a-176ca4d40717"},"relationshipType":"ChildOf"}]},
{"operationName":"GET:io.qstudio.practice.mpopentracing.HelloOpenTracing.sayHello","spanContext":{"spanId":"7c39b334-401e-4585-a850-169e2200faba","traceId":"a1fe155e-eb45-4070-b29a-176ca4d40717"},"startTime":"2020-03-07T19:35:12.331465+08:00[Asia/Taipei]","endTime":"2020-03-07T19:35:42.389461+08:00[Asia/Taipei]","traceDuration":"30057640000","spanTags":[{"component": "jaxrs"},{"span.kind": "server"},{"http.url": "http://localhost:8080/api/hello"},{"http.method": "GET"}],"references":[{"spanContext":{"spanId":"9bc20e68-ca75-47c2-b03f-44ffa0ecdb64","traceId":"a1fe155e-eb45-4070-b29a-176ca4d40717"},"relationshipType":"ChildOf"}]},
{"operationName":"io.qstudio.practice.mpopentracing.MessageGenerator.getMessage","spanContext":{"spanId":"d7edb66a-2840-471e-a5ee-3d6ff0440b7d","traceId":"a1fe155e-eb45-4070-b29a-176ca4d40717"},"startTime":"2020-03-07T19:35:12.384+08:00[Asia/Taipei]","endTime":"2020-03-07T19:35:42.389507+08:00[Asia/Taipei]","traceDuration":"30005503000","references":[{"spanContext":{"spanId":"7c39b334-401e-4585-a850-169e2200faba","traceId":"a1fe155e-eb45-4070-b29a-176ca4d40717"},"relationshipType":"ChildOf"},{"spanContext":{"spanId":"9bc20e68-ca75-47c2-b03f-44ffa0ecdb64","traceId":"a1fe155e-eb45-4070-b29a-176ca4d40717"},"relationshipType":"ChildOf"}]}
]}]]

眼尖的你可能會注意到,這不是個 JSON 嗎?對的,追蹤的報告是個 JSON 字串。格式化以後如下:

{
    "traceSpans": [
        {
            "operationName": "processContainerRequest",
            "spanContext": {
                "spanId": "d262cf8b-9fd4-42c4-bb14-b85464614d7c",
                "traceId": "a1fe155e-eb45-4070-b29a-176ca4d40717"
            },
            "startTime": "2020-03-07T19:35:12.084300+08:00[Asia/Taipei]",
            "endTime": "2020-03-07T19:35:42.456846+08:00[Asia/Taipei]",
            "traceDuration": "30372546000",
            "spanTags": [
                {
                    "Server": "server"
                },
                {
                    "Domain": "domain1"
                }
            ]
        },
        {
            "operationName": "processWebserviceRequest",
            "spanContext": {
                "spanId": "9bc20e68-ca75-47c2-b03f-44ffa0ecdb64",
                "traceId": "a1fe155e-eb45-4070-b29a-176ca4d40717"
            },
            "startTime": "2020-03-07T19:35:12.229490+08:00[Asia/Taipei]",
            "endTime": "2020-03-07T19:35:42.447342+08:00[Asia/Taipei]",
            "traceDuration": "30217839000",
            "spanTags": [
                {
                    "accept-language": "[zh-TW,en;q=0.5]"
                },
                {
                    "ResponseStatus": "200"
                },
                {
                    "host": "[localhost:8080]"
                },
                {
                    "upgrade-insecure-requests": "[1]"
                },
                {
                    "connection": "[keep-alive]"
                },
                {
                    "Method": "GET"
                },
                {
                    "URL": "http://localhost:8080/api/hello"
                },
                {
                    "accept-encoding": "[gzip, deflate]"
                },
                {
                    "user-agent": "[Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:73.0) Gecko/20100101 Firefox/73.0]"
                },
                {
                    "accept": "[text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8]"
                }
            ],
            "references": [
                {
                    "spanContext": {
                        "spanId": "d262cf8b-9fd4-42c4-bb14-b85464614d7c",
                        "traceId": "a1fe155e-eb45-4070-b29a-176ca4d40717"
                    },
                    "relationshipType": "ChildOf"
                }
            ]
        },
        {
            "operationName": "GET:io.qstudio.practice.mpopentracing.HelloOpenTracing.sayHello",
            "spanContext": {
                "spanId": "7c39b334-401e-4585-a850-169e2200faba",
                "traceId": "a1fe155e-eb45-4070-b29a-176ca4d40717"
            },
            "startTime": "2020-03-07T19:35:12.331465+08:00[Asia/Taipei]",
            "endTime": "2020-03-07T19:35:42.389461+08:00[Asia/Taipei]",
            "traceDuration": "30057640000",
            "spanTags": [
                {
                    "component": "jaxrs"
                },
                {
                    "span.kind": "server"
                },
                {
                    "http.url": "http://localhost:8080/api/hello"
                },
                {
                    "http.method": "GET"
                }
            ],
            "references": [
                {
                    "spanContext": {
                        "spanId": "9bc20e68-ca75-47c2-b03f-44ffa0ecdb64",
                        "traceId": "a1fe155e-eb45-4070-b29a-176ca4d40717"
                    },
                    "relationshipType": "ChildOf"
                }
            ]
        },
        {
            "operationName": "io.qstudio.practice.mpopentracing.MessageGenerator.getMessage",
            "spanContext": {
                "spanId": "d7edb66a-2840-471e-a5ee-3d6ff0440b7d",
                "traceId": "a1fe155e-eb45-4070-b29a-176ca4d40717"
            },
            "startTime": "2020-03-07T19:35:12.384+08:00[Asia/Taipei]",
            "endTime": "2020-03-07T19:35:42.389507+08:00[Asia/Taipei]",
            "traceDuration": "30005503000",
            "references": [
                {
                    "spanContext": {
                        "spanId": "7c39b334-401e-4585-a850-169e2200faba",
                        "traceId": "a1fe155e-eb45-4070-b29a-176ca4d40717"
                    },
                    "relationshipType": "ChildOf"
                },
                {
                    "spanContext": {
                        "spanId": "9bc20e68-ca75-47c2-b03f-44ffa0ecdb64",
                        "traceId": "a1fe155e-eb45-4070-b29a-176ca4d40717"
                    },
                    "relationshipType": "ChildOf"
                }
            ]
        }
    ]
}

追蹤結果的資訊極度詳盡,連 user-agent 都包括在內,而且有上下結構關係,每個被追蹤的方法都描述得一清二楚。從範例就能看出來,主要的時間都是花在 io.qstudio.practice.mpopentracing.MessageGenerator.getMessage,共耗費了 30005503000 奈秒(約 30 秒)。這麼好用的工具,下個參數就啟動,既方便使用,生出的追蹤報告又有科學數據,真的愜意!(爽

當然,MPOpenTracing 功能不只如此,還有和 MPConfig 的整合、手動寫追蹤紀錄等等,大家如果有需要,還請閱讀規格書。


文末,做個簡單的結語,

MPOpenTracingMicroProfile 內建了追蹤的機制,預設就可以對 RESTful API 進行追蹤,還提供了簡單的方法讓開發者決定哪些邏輯需要被追蹤,大幅簡化了實作追蹤邏輯所需的工作。若有追蹤服務實際運作情形的需求,不妨考慮在測試環境啟動本機制,留下可以協助查出問題的紀錄!!!

by Arren Ping

results matching ""

    No results matching ""