MicroProfile OpenTracing・哪邊有問題？
如果碰到系統運作不順暢，或者說有點慢，你們會怎麼做呢？
或許很多開發者會和我一樣選擇最簡單的方法 => 插個 旗子。大概的做法就是：
- 找到可能的問題邏輯
- 在執行前先取得系統時間，並印出一些訊息
- 在執行後取得系統時間，計算執行時長，再印出一些訊息
這是非常實用的技巧，在開發的前期階段經常會用到，可以幫助快速找出問題。
但隨著專案的演進，模組、系統逐漸長大，插旗雖然簡單，但似乎變得有點麻煩。手動一層一層插旗，再手動一層一層移除，持續考驗著開發者的耐性。隨著工具的演進，有了 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 的準備。
如何追蹤？
其實，可以什麼都不用做。
是的，你沒看錯，什麼都不用做，就可以自動追蹤了！但這是有前提的：
- 滿足被追蹤的條件。PayaraMicro 上預設請求執行超過 30 秒以上，就滿足了追蹤的條件。
- 追蹤的範圍是來自
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!";
}
}
範例很簡單，呼叫 MessageGenerator 的 getMessage 時會睡 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 的整合、手動寫追蹤紀錄等等，大家如果有需要，還請閱讀規格書。
文末，做個簡單的結語，
MPOpenTracing 讓 MicroProfile 內建了追蹤的機制，預設就可以對 RESTful API 進行追蹤，還提供了簡單的方法讓開發者決定哪些邏輯需要被追蹤，大幅簡化了實作追蹤邏輯所需的工作。若有追蹤服務實際運作情形的需求，不妨考慮在測試環境啟動本機制，留下可以協助查出問題的紀錄！！！
by Arren Ping