Observability Pt. 3: Manual Tracing Instrumentation with OpenTelemetry

สวัสดีครับเพื่อน ๆ ทุกท่าน ก็มาพบกันอีกครั้งสำหรับบทความในซีรีย์ Observability ครั้งนี้ก็เป็นตอนที่ 3 แล้ว ตอนแรกก็กะว่าจะจบเรื่องของ Tracing ตั้งแต่ตอนที่ 2 แล้วบทความตอนนี้ก็จะขึ้นเรื่องใหม่ แต่ผมรู้สึกว่ายังมีรายละเอียดในเรื่องของ Tracing บางส่วนที่ผมไม่ได้เขียนถึง จึงขอเขียนเพิ่มเติมอีกซักตอนเพื่อให้ได้เนื้อหาสาระที่ครบถ้วน

ในคราวที่แล้ว เราได้พูดถึงคอนเซ็ปต์ของการทำ Tracing รวมถึงได้ทดลองทำ Tracing โดยใช้ Tools คือ Jaeger เป็น Backend กับ Library OpenTelemetry โดยเราได้ใช้งาน OpenTelemetry ในแบบที่เรียกว่า Automatic Instrumentation ซึ่งเป็นการที่เราใช้ Agent ของ OpenTelemetry เข้าไปจับการทำงานของ Application ของเราในแบบอัตโนมัติโดยไม่ต้องมีการแก้ไข Source Code ใด ๆ

ในการใช้งาน Tracing ในแบบ Automatic นั้น จะสังเกตว่า Span หรือแต่ละขั้นตอนย่อยที่เราเห็นนั้น หลัก ๆ จะเห็นในส่วนที่เป็นข้อต่อ ระหว่างส่วนประกอบต่าง ๆ ของ Application ที่มีการเรียกข้ามกัน เช่น เห็นจุดที่โปรแกรมมีการเรียกใช้งาน Database มีการเรียกใช้งาน API อื่น​ หรือเป็นการเรียกข้ามกันระหว่าง Layer ใน Application เช่น จากตัวอย่างที่แล้วของเราที่เป็น Spring Boot Application ก็จะเห็นการทำงานเมื่อมี Request วิ่งเข้ามาในแต่ละ Layer เช่น Controller หรือ Repository เป็นต้น

ทีนี้ถ้าหากว่าข้อมูลที่เราเห็นจากการทำ Automatic Instrumentation มันไม่เห็นข้อมูลในจุดที่เราต้องการล่ะ เราจะเพิ่มให้มีข้อมูล Trace ในจุดที่เราต้องการได้อย่างไร ในบทความตอนนี้เราจะมาดูวิธีการกันครับ

เตรียมความพร้อมก่อนเริ่มทดลอง

ขอทบทวนนิดนึง สำหรับบทความนี้จะใช้ Source Code ตัวนี้ อย่าง Repository นี้ โดยโปรแกรมที่ต้องการ คือ Git, Java 17 และ Docker สำหรับรายละเอียดเพิ่มเติมสามารถอ่านได้ที่บทความตอนที่ 2 นะครับ

ในการรันโปรแกรม มีขั้นตอนคร่าว ๆ ดังนี้

1. Start โปรแกรม Jaeger โดยใช้คำสั่ง Docker ดังนี้

docker run --name jaeger \
  -e COLLECTOR_ZIPKIN_HOST_PORT=:9411 \
  -e COLLECTOR_OTLP_ENABLED=true \
  -p 5775:5775/udp \
  -p 6831:6831/udp \
  -p 6832:6832/udp \
  -p 5778:5778 \
  -p 16686:16686 \
  -p 4317:4317 \
  -p 4318:4318 \
  -p 14250:14250 \
  -p 14268:14268 \
  -p 14269:14269 \
  -p 9411:9411 \
  jaegertracing/all-in-one:latest

จุดนี้ต้องอย่าลืมใส่ Parameter -e COLLECTOR_OTLP_ENABLED=true เพื่อเปิดใช้งาน Port ของ Jaeger Collection ที่รองรับ OpenTelemetry Protocol ด้วย (Port 4317 และ 4318) เนื่องจากเราจะให้ตัว OpenTelemetry Agent คุยกับตัว Jaeger Collector ด้วย OpenTelemetry Protocol ซึ่งเป็นค่า Default

2. Clone Repository ของโปรแกรมที่เราจะใช้ทดสอบลงมาก่อน

git clone https://github.com/tinnapat/spring-petclinic-opentelemetry.git

บน Repository ตัวนี้จะมี 2 Branch โดย Default Branch ชื่อ main จะเป็นโค้ดที่ยังไม่มีการเพิ่มในส่วนของการใช้งาน Manual Instrumentation เข้าไป ส่วน Branch ชื่อ manual-instrumentation จะเป็นโค้ดที่มีการเพิ่มการใช้งาน Manual Instrumentation เข้าไปแล้ว

3. Build เป็น Jar File โดยใช้คำสั่ง

cd spring-petclinic-opentelemetry
./mvnw package

4. รันโปรแกรม โดยใช้คำสั่ง java -jar โดย Parameter ต่าง ๆ ที่เราส่งไปให้กับ OpenTelemetry สามารถส่งได้ 2 วิธี คือผ่าน (1) JVM Parameter เช่น

java -javaagent:opentelemetry-javaagent.jar \
  -Dotel.service.name=spring-petclinic \
  -Dotel.metrics.exporter=none; \
  -jar target/*.jar

หรือ (2) ใช้ Environment Variable ก็ได้ เช่น

export OTEL_METRICS_EXPORTER=none
export OTEL_SERVICE_NAME=spring-petclinic

java -javaagent:opentelemetry-javaagent.jar -jar target/*.jar

ก็สามารถเลือกใช้ได้ตามสะดวกครับ

5. เข้าโปรแกรมได้จาก http://localhost:8080/

6. หลังจากใช้งานโปรแกรม สามารถดูข้อมูล Trace ได้ที่ http://localhost:16686/

เริ่มลงมือกันเลย

เดี๋ยวเราเริ่มกันเลยดีกว่าครับ อันดับแรกมาดูก่อนว่าถ้าเราใช้งานแบบ Automatic Instrumentation โดยที่ไม่แก้ไขอะไรเลย เราจะเห็นอะไรบ้าง

ผมเข้ามาที่หน้า Find Owners โดยกดเมนูทางด้านบน

จากนั้นกดปุ่ม Find Owner โดยไม่ใส่ข้อมูลใด ๆ จะได้หน้าจอดังนี้

ถ้าลองเข้าหน้าจอ Jaeger UI ไปดูที่ Trace อันสุดท้าย จะเจอข้อมูล Trace ดังนี้

จะเห็นว่าข้อมูลที่เราเห็นด้วย Automatic Instrumentation นั้น จะเป็นข้อมูลในแต่ละ Layer ของ Application ไม่ว่า จะเป็นข้อต่อกับภายนอก เช่น ขั้นตอนที่มีการติดต่อไปหา Database หรือข้อต่อภายใน เช่น ระหว่าง Tier ต่าง ๆ ใน Application เช่น Controller, Repository เป็นต้น

จาก Trace ข้างต้น จะมีข้อมูล Trace แรกที่ /owner ก็คือระดับ HTTP Request ที่เข้ามาที่ App Server คือ Tomcat จากนั้นก็จะเป็น Layer ของ Controller ซึ่งก็คือ OwnerController.processFindForm และ Repository ซึ่งก็คือ OwnerRepository.findByLastName

ทีนี้ ผมเข้ามาดูที่ Source Code พบว่า Method OwnerController.processFindForm นั้น มีการเรียกใช้อีกหลาย Method เช่น findPaginatedForOwnersLastName และ addPaginationModel ด้วย เป็นต้น

 @GetMapping("/owners")
 public String processFindForm(@RequestParam(defaultValue = "1") int page, Owner owner, BindingResult result,
   Model model) {
  // allow parameterless GET request for /owners to return all records
  if (owner.getLastName() == null) {
   owner.setLastName(""); // empty string signifies broadest possible search
  }

  // find owners by last name
  Page<Owner> ownersResults = findPaginatedForOwnersLastName(page, owner.getLastName());
  if (ownersResults.isEmpty()) {
   // no owners found
   result.rejectValue("lastName", "notFound", "not found");
   return "owners/findOwners";
  }

  if (ownersResults.getTotalElements() == 1) {
   // 1 owner found
   owner = ownersResults.iterator().next();
   return "redirect:/owners/" + owner.getId();
  }

  // multiple owners found
  return addPaginationModel(page, model, ownersResults);
 }

สมมุติว่าถ้าเราต้องการเห็นขั้นตอนของ Method OwnerController.addPaginationModel ด้วย เราต้องทำอย่างไร

1. Configure ด้วย OpenTelemetry Parameter

วิธีแรกเป็นวิธีที่ไม่ต้องแก้โค้ด ซึ่งอาจจะยังเรียกว่าเป็นการใช้งาน Automatic Instrumentation อยู่ โดยเราสามารถใช้ Prarameter ดังนี้ ในการระบุ Method ที่เราต้องการให้ปรากฏใน Trace

กรณีใช้ Environment Variable

export OTEL_INSTRUMENTATION_METHODS_INCLUDE=org.springframework.samples.petclinic.owner.OwnerController[addPaginationModel]

กรณีใช้ JVM Parameter

-Dotel.instrumentation.methods.include=org.springframework.samples.petclinic.owner.OwnerController[addPaginationModel]

จากนั้นลองใช้งานโปรแกรมแบบเดิม แล้วดู Trace ผ่าน Jaeger UI จะเห็นว่ามี Trace ของ Method OwnerController.addPaginationModel ปรากฏขึ้นมาแล้ว

สมมุติว่าเราอยากทำแบบเดียวกันนี้ กับ Method OwnerController.findPaginatedForOwnersLastName บ้าง แต่เดี๋ยวเราจะทำด้วยคนละวิธีกันครับ

2. ใช้ Annotation @WithSpan

สำหรับวิธีที่สองคือวิธีที่ต้องแก้โค้ดครับ โดยเราสามารถใส่ Annotation @WithSpan บนหัวของ Method ที่เราต้องการให้มีข้อมูล Trace

เนื่องจากต้องมีการแก้ไขโค้ด ก็ต้องเริ่มต้นจากการเพิ่ม Dependency ก่อน โดยให้ใช้ Version ที่ตรงกับของ OpenTelemetry Agent นะครับ

    <dependency>
      <groupId>io.opentelemetry.instrumentation</groupId>
      <artifactId>opentelemetry-instrumentation-annotations</artifactId>
      <version>1.26.0</version>
    </dependency>

จากนั้นเพิ่ม Annotation @WithSpan เข้าไปที่หัว Method ที่ต้องการให้มีข้อมูล Trace

import io.opentelemetry.instrumentation.annotations.WithSpan;
 
@WithSpan
private Page<Owner> findPaginatedForOwnersLastName(
    @SpanAttribute("page") int page,
    @SpanAttribute("lastName") String lastname) {
  int pageSize = 5;
  Pageable pageable = PageRequest.of(page - 1, pageSize);
  return owners.findByLastName(lastname, pageable);
}

จากตัวอย่างข้างต้น เรายังสามารถใช้ Annotation @SpanAttribute ในการบันทึก Parameter ของ Method นี้เข้าไปเป็น Attribute ของ Span ได้อีกด้วย โดยในกรณีของ Jaeger จะเห็นข้อมูลอยู่ในส่วนของ Tag

เนื่องจากมีการแก้โค้ด หลังจากขั้นตอนนี้ก็ต้องทำการ Build Jar File ใหม่ก่อนนะครับ หลังจากที่เราทดลองเรียกโปรแกรมอีกครั้งหนึ่งไปดู Trace ก็จะเห็นข้อมูลของ Method OwnerController.findPaginatedForOwnersLastName ขึ้นมา โดยจะเห็น Parameter ของ Method ที่เราใส่ Annotation @SpanAttribute เอาไว้ ซึ่งก็คือ “page” และ “lastName” ปรากฏขึ้นเป็น Tag ของ Span ด้วย

3. ใช้ OpenTelemetry Trace API

สำหรับการใช้งาน OpenTelemetry API จะเริ่มจากการ Get Object OpenTelemetry โดยใช้ Method GlobalOpenTelemetry.get() จากนั้น Get Object Tracer มาจาก Object OpenTelemetry และเราจะนำ Object Tracing ไปใช้สร้าง Object Span เพื่อทำการบันทึกเวลาที่ใช้ในโค้ดออกมาเป็น Span ต่อไป

เนื่องจาก Application ของเราเป็น Spring Boot Application และ Object Tracer เราสามารถใช้เป็น Singleton ได้ ดังนั้นเราเริ่มจากการ Register Tracer เป็น Spring Bean ก่อน

@Bean
public OpenTelemetry openTelemetry() {
  return GlobalOpenTelemetry.get();
}
 
@Bean
public Tracer tracer(OpenTelemetry openTelemetry) {
  return openTelemetry.getTracer("tech.kbtg.demo.observability.spring-petclinic");
} 

สำหรับในโค้ดที่เราต้องการสร้าง Span เราต้องได้ Object Tracer มาก่อน จากนั้นเราสามารถสร้าง Span โดยใช้ Method tracer.spanBuilder() ซึ่งเราสามารถระบุชื่อของ Span และ Attribute (หรือ Tag ใน Jaeger) ได้ด้วย ตามตัวอย่าง

@Autowired
private Tracer tracer; 

@GetMapping("/owners")
public String processFindForm(@RequestParam(defaultValue = "1") int page, Owner owner, BindingResult result,
   Model model) {

  Span span = tracer.spanBuilder("Validate last name")
     .setAttribute("lastName", owner.getLastName())
     .startSpan();

  try {
   // allow parameterless GET request for /owners to return all records
   if (owner.getLastName() == null) {
    owner.setLastName(""); // empty string signifies broadest possible search
   }
  }
  finally {
   span.end();
  }

  ...
 }

Method setAttribute เป็นการบันทึกข้อมูลใด ๆ ลงใน Span ซึ่งกรณีใช้ Jaeger เป็น Backend ข้อมูลตรงนี้ จะปรากฏในส่วนของ Tag

ใช้ Method span.end() ในการบันทึกจุดสิ้นสุดของ Span ใน Finally Block เพื่อให้ Span ถูกบันทึกเวลาจบเสมอถึงแม้จะมีเหตุการณ์หรือ Error ที่ไม่คาดคิดเกิดขึ้น

เมื่อเรารันโปรแกรมนี้ จะเห็นข้อมูล Trace ดังนี้

จะเห็นว่าชื่อของ Span คือค่าที่เราใส่เข้าไปใน tracer.spanBuilder() ซึ่งก็คือ “Validate last name” และค่าของ Tag “lastName” ตามที่เราเขียนในโค้ดว่าให้บันทึกไว้ด้วย ในขณะที่ค่าของ otel.library.name คือค่าที่เราใช้ตอนสร้าง Object Tracer นั่นเอง

สรุปว่าวันนี้เราได้นำเสนอ 3 วิธีในการบันทึกข้อมูล Trace ในจุดที่เราต้องการเพิ่มเติมนอกเหนือไปจากข้อมูลที่ได้จากการใช้งาน OpenTelemetry แบบ Automatic Instrumentation กล่าวโดยสรุปได้ดังนี้

1. ใช้ Configuration Parameter

System property: otel.instrumentation.methods.include
Environment variable: OTEL_INSTRUMENTATION_METHODS_INCLUDE

ที่เราสามารถระบุชื่อ Method ที่ต้องการบันทึก Trace ลงไปได้เลย ข้อดีของวิธีการนี้คือไม่ต้องแก้โค้ด แต่ความยืดหยุ่นจะน้อยที่สุด เนื่องจากไม่สามารถตั้งชื่อ Span และเพิ่ม Attribute ใด ๆ ลงไปใน Span ได้ และขอบเขตของ Span ก็จะครอบคลุมทั้ง Method ที่เรากำหนด

2. ใช้ Annotation @WithSpan

วิธีนี้จำเป็นต้องมีการเพิ่ม Dependency ของ OpenTelemetry Library เข้าไปใน Application และนำ Annotation ไปใส่ในหัวของ Method ที่ต้องการ ขอบเขตของ Span ก็จะกินทั้ง Method เหมือนกับวิธีที่ 1 ข้างต้น แต่จะยืดหยุ่นมากกว่า เนื่องจากสามารถใช้ Annotation อื่น ๆ ประกอบเพื่อสามารถบันทึก Parameter ของ Method เข้าไปเป็น Attribute ของ Span ได้ อาจจะไม่มีตัวอย่างไว้ในบทความนี้ แต่สามารถศึกษาเพิ่มเติมได้ที่

Annotations

3. ใช้ Tracer API

วิธีสุดท้ายนี้จะต้องเขียนโค้ดเพิ่มมากกว่าวิธีอื่น แต่ก็เป็นจำนวนเล็กน้อยเท่านั้น เป็นวิธีที่มีความยืนหยุ่นมากที่สุด เนื่องจากเราสามารถกำหนดจุดเริ่มต้นและจุดสิ้นสุดของ Span เองได้ และยังสามารถตั้งชื่อ Span รวมถึงสามารถเพิ่ม Attribute ต่าง ๆ เข้าไปใน Span ได้ตามต้องการ

สำหรับบทความในตอนที่ 3 นี้ก็ขอจบแต่เพียงเท่านี้นะครับ หวังว่าผู้อ่านจะได้ความรู้ไปไม่มากก็น้อย ดังที่เคยกล่าวไปแล้ว ตัว OpenTelemetry API นั้นไม่ได้ทำเฉพาะเรื่องของ Tracing เท่านั้น แต่ยังรวมไปถึงการทำ Logging และ Metrics อีกด้วย ไว้ถ้ามีโอกาสจะได้มาเขียนถึงคุณสมบัติด้านอื่น ๆ บ้างครับ

ถ้าต้องการดู Source Code ที่มีการแก้ไขตามบทความนี้แล้ว สามารถดูได้ใน GitHub Repository ตัวเดิม โดยอยู่ใน Branch ชื่อ manual-instrumentation ครับ

Source Code หลังแก้ไข อยู่ใน Branch ชื่อ manual-instrumentation

อ่านบทความอื่นๆ ในซีรีย์ Observability

Observability Pt. 1: ทำความรู้จักกับ Observability กันเถอะ

Observability Pt. 2: Tracing with OpenTelemetry and Jaeger

สำหรับใครที่ชื่นชอบบทความนี้ อย่าลืมกดติดตาม Medium: KBTG Life เรามีสาระความรู้และเรื่องราวดีๆ จากชาว KBTG พร้อมเสิร์ฟให้ที่นี่ที่แรก