מדוע לוגים מפסיקים להיות שימושיים במערכות אמיתיות

TL;DR: לוגים בסיסיים עובדים היטב עבור תהליכים פשוטים, אך ברגע שמופיעים מקביליות, עיכובים ומשתמשים מרובים, הם מפסיקים לספר סיפורים מלאים.

2025-10-19 22:55:56,577 INFO demo.DemoApplication Starting DemoApplication using Java 24.0.1 with PID 188600 (/home/john-doe/Projects/demo/target/classes started by john_doe in /home/john-doe/Projects/demo) 2025-10-19 22:55:56,581 INFO demo.DemoApplication No active profile set, falling back to 1 default profile: "default" 2025-10-19 22:55:57,198 INFO o.s.boot.web.embedded.tomcat.TomcatWebServer Tomcat initialized with port 8080 (http) 2025-10-19 22:55:57,204 INFO org.apache.coyote.http11.Http11NioProtocol Initializing ProtocolHandler ["http-nio-8080"] 2025-10-19 22:55:57,205 INFO org.apache.catalina.core.StandardService Starting service [Tomcat] 2025-10-19 22:55:57,205 INFO org.apache.catalina.core.StandardEngine Starting Servlet engine: [Apache Tomcat/10.1.46] 2025-10-19 22:55:57,223 INFO o.a.c.c.ContainerBase.[Tomcat].[localhost].[/] Initializing Spring embedded WebApplicationContext 2025-10-19 22:55:57,223 INFO o.s.b.w.s.c.ServletWebServerApplicationContext Root WebApplicationContext: initialization completed in 589 ms 2025-10-19 22:55:57,426 INFO org.apache.coyote.http11.Http11NioProtocol Starting ProtocolHandler ["http-nio-8080"] 2025-10-19 22:55:57,431 INFO o.s.boot.web.embedded.tomcat.TomcatWebServer Tomcat started on port 8080 (http) with context path '/' 2025-10-19 22:55:59,568 INFO o.s.boot.web.embedded.tomcat.GracefulShutdown Commencing graceful shutdown. Waiting for active requests to complete 2025-10-19 22:55:59,571 INFO o.s.boot.web.embedded.tomcat.GracefulShutdown Graceful shutdown complete

הודות למושג הלוגים, קל יותר להבין מה קורה במערכת פעילה – במיוחד כאשר מתחילות להופיע בעיות.

הדוגמה לעיל מציגה את ההפעלה והכיבוי של שירות Spring Framework, מראה נפוץ מאוד ביישומי Java ארגוניים. Logback משמש לעתים קרובות כ-backend לרישום לוגים.

במאמר זה, נתחיל תחילה בבחינת תיעוד הרישום בצורתו הבסיסית ביותר, ולאחר מכן נשפר בהדרגה את התצורה באפליקציה שלנו. המטרה הסופית פשוטה: פתרון שמקצר את הזמן הנדרש להבנת מה השתבש.

למרות שהדוגמאות מתמקדות ב-Logback, הרעיונות אינם ספציפיים לו. ניתן להשיג תוצאות דומות ללא תלות בטכנולוגיה, בשפת תכנות או במסגרת.

הבנת היסודות

הבעיה המרכזית שלוגים אמורים לעזור לפתור היא קביעה כאשר ו מה בדיוק קרה.

הבה נבחן מקרוב את הלוגים בתצורה המינימלית שלהם:

2025-10-18 16:02:35,338 INFO demo.HelloPrinter Hello world 2025-10-18 16:02:35,838 INFO demo.HelloPrinter How are you 2025-10-18 16:02:36,339 INFO demo.HelloPrinter Good bye | | | | | | | +--- ההודעה | | | | | +--- שם המחלקה | | | +--- רמת הלוג | +--- חותמת זמן

סדר כרונולוגי מובטח בשתי דרכים.

ראשית, חתימת הזמן מציגה את סדר האירועים. שנית, מבנה נתוני הלוג עצמו מאפשר רק הוספת רשומות חדשות, ובכך מבטיח שקריאת הלוגים מלמעלה למטה משמרת את הרצף.

'רמת לוג' מבדילה בין התנהגות צפויה (DEBUG, INFO) לבעיות פוטנציאליות (WARN, ERROR). 'שם המחלקה' אומר לנו היכן בקוד הופק הלוג. 'ההודעה' היא טקסט מותאם אישית שהוכן על ידי המפתח.

הבה נוודא שזה תואם לקוד:

package demo; import org.slf4j.Logger; import org.slf4j.LoggerFactory; import org.springframework.stereotype.Component; @Component public class HelloPrinter { private static final Logger logger = LoggerFactory.getLogger(HelloPrinter.class); public void print() { logger.info("Hello world"); logger.info("How are you"); logger.info("Good bye"); } }

עד כה, הכל מתנהג בדיוק כמצופה.

תצורת Logback (מינימלית אך מספקת)

כדי להפיק לוגים בפורמט זה באמצעות Logback, נעשה שימוש בתצורה הבאה:

<configuration> <appender name="Console" class="ch.qos.logback.core.ConsoleAppender"> <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder"> <pattern> %d{ISO8601} %highlight(%-5level) %yellow(%-48logger{48}) %msg %n%throwable </pattern> </encoder> </appender> <!-- root level="INFO" means I don't want to see DEBUG or TRACE. Without it at the Spring server start we would see a lot o DEBUG logs related to Spring Framework internals --> <root level="INFO"> <appender-ref ref="Console"/> </root> </configuration>

מרכיבים עיקריים:

  • חתימת זמן,
  • רמת לוג (רוחב קבוע לקריאות),
  • שם מחלקה / לוגר,
  • הודעה,
  • מעקב מחסנית אופציונלי.
%d{ISO8601} %-5level %-48logger{48} %msg %n%throwable | | | | | | | | | | | +--- פלט מחסנית מודפס בצורה יפה | | | | | …במקרה שהיה חריג | | | | | | | | | +--- שורה חדשה להפרדת שורת הלוג | | | | | | | +--- ההודעה | | | | | +--- שם המחלקה / הלוגר | | …מצביע על מקום בקוד המקור שמייצר את הלוג הזה | | …באורך של בדיוק 48 תווים, לקריאה נוחה | | | +--- רמת הלוג | …באורך של בדיוק 5 תווים | …ERROR הוא 5 תווים, אבל INFO הוא רק 4 | …ואנחנו רוצים לשמור על עקביות | +--- חתימת זמן

הגדרה זו נקייה, קריאה ועובדת היטב –עד שהמציאות מתערבת. 

❌ בעיה: משתמשים במקביל מטשטשים את הסיפור

כעת נבחן תרחיש מציאותי немного יותר.

שלושה משתמשים משנים הזמנות בו-זמנית. כמות, מחיר פריט ומחיר כולל נרשמים במקומות שונים:

2025-10-18 16:56:28,415 INFO demo.PrintingDemo מחיר הפריט = 15 2025-10-18 16:56:28,465 INFO demo.PrintingDemo מחיר הפריט = 36 2025-10-18 16:56:28,571 INFO demo.PrintingDemo פריטים בהזמנה = [1] 2025-10-18 16:56:28,581 INFO demo.PrintingDemo מחיר הפריט = 47 2025-10-18 16:56:28,611 INFO demo.PrintingDemo פריטים בהזמנה = [5] 2025-10-18 16:56:28,640 INFO demo.PrintingDemo מחיר כולל = 75 2025-10-18 16:56:28,714 INFO demo.PrintingDemo מחיר כולל = 36 2025-10-18 16:56:28,715 INFO demo.PrintingDemo פריטים בהזמנה = [3] 2025-10-18 16:56:28,746 INFO demo.PrintingDemo מחיר כולל = 141

בשלב זה, הלוגים כבר אינם שימושיים. איננו יכולים לקבוע:

  • אילו אירועים שייכים לאותה הזמנה,
  • האם הסכומים מחושבים נכון,
  • או איזה משתמש הפעיל איזו רצף.

✅ פתרון שנוסה: PID ומזהה תהליך (thread ID)

אם אתה משתמש ב-Spring Boot (שברירת המחדל שלו היא Logback), תצורת ברירת המחדל כבר כוללת:

  • מזהה תהליך (PID),
  • מזהה תהליך.

בואו נבהיר אותם בתבנית:

%d{ISO8601} %-5level ${PID} [t=%thread] %-48logger{48} %msg %n%throwable | | | +--- מזהה תהליך | …עם שיפור ויזואלי קטן | …ייראה כך: [t=Thread-1] | +--- PID

PID מסייע להבחין:

  • מופעי שירות שונים,
  • הפעלות מחדש,
  • פריסות מרובות מופעים.

מזהה תהליך (Thread ID) מסייע להציג:

  • אילו בקשות מטופלות במקביל,
  • אילו נתיבי הרצה פועלים במקביל.

עם שינוי זה, אותו תרחיש הופך לקל יותר למעקב:

2025-10-18 17:02:51,199 INFO 151993 [t=Thread-2] demo.PrintingDemo Price of item = 63 2025-10-18 17:02:51,206 INFO 151993 [t=Thread-1] demo.PrintingDemo Price of item = 34 2025-10-18 17:02:51,223 INFO 153222 [t=Thread-1] demo.PrintingDemo Price of item = 58 2025-10-18 17:02:51,246 INFO 151993 [t=Thread-5] demo.PrintingDemo Price of item = 94 2025-10-18 17:02:51,331 INFO 151993 [t=Thread-2] demo.PrintingDemo Items in order = [1] 2025-10-18 17:02:51,354 INFO 151993 [t=Thread-2] demo.PrintingDemo Total price = 63 2025-10-18 17:02:51,355 INFO 153222 [t=Thread-1] demo.PrintingDemo Items in order = [4] 2025-10-18 17:02:51,355 INFO 151993 [t=Thread-4] demo.PrintingDemo Price of item = 68 2025-10-18 17:02:51,358 INFO 151993 [t=Thread-5] demo.PrintingDemo Items in order = [2] 2025-10-18 17:02:51,367 INFO 151993 [t=Thread-1] demo.PrintingDemo Items in order = [2] 2025-10-18 17:02:51,371 INFO 151993 [t=Thread-1] demo.PrintingDemo Total price = 68 2025-10-18 17:02:51,429 INFO 153222 [t=Thread-1] demo.PrintingDemo Total price = 232 2025-10-18 17:02:51,456 INFO 151993 [t=Thread-5] demo.PrintingDemo Total price = 188 2025-10-18 17:02:51,460 INFO 151993 [t=Thread-4] demo.PrintingDemo Items in order = [5] 2025-10-18 17:02:51,629 INFO 151993 [t=Thread-4] demo.PrintingDemo Total price = 340

על ידי סינון לפי thread ו-PID, נוכל סוף סוף לשחזר הזמנה בודדת.

2025-10-18 17:02:51,206 INFO 151993 [t=Thread-1] demo.PrintingDemo מחיר הפריט = 34 2025-10-18 17:02:51,367 INFO 151993 [t=Thread-1] demo.PrintingDemo פריטים בהזמנה = [2] 2025-10-18 17:02:51,371 INFO 151993 [t=Thread-1] demo.PrintingDemo מחיר כולל = 68

❌ בעיה: זמן והיקף שוברים את הגישה הזו

פתרון זה עובד רק כאשר אנו יודעים בדיוק מתי התרחשה הבעיה.

במערכות אמיתיות:

  • משתמשים מדווחים על תקלות שעות לאחר מכן,
  • תהליכונים נעשים בהם שימוש חוזר,
  • מאות הרצות חופפות.

שקול לוגים כגון:

2025-10-19 18:29:53,428 INFO 169232 [t=Thread-2] demo.PrintingDemo Price of item = 2 2025-10-19 18:29:53,467 INFO 169232 [t=Thread-3] demo.PrintingDemo Price of item = 9 2025-10-19 18:29:53,484 INFO 169232 [t=Thread-1] demo.PrintingDemo Price of item = 26 2025-10-19 18:29:53,493 INFO 169232 [t=Thread-2] demo.PrintingDemo Items in order = [2] 2025-10-19 18:29:53,529 INFO 169232 [t=Thread-3] demo.PrintingDemo Items in order = [5] 2025-10-19 18:29:53,545 INFO 169232 [t=Thread-1] demo.PrintingDemo Items in order = [3] 2025-10-19 18:29:53,631 INFO 169232 [t=Thread-1] demo.PrintingDemo Total price = 78 2025-10-19 18:29:53,645 INFO 169232 [t=Thread-2] demo.PrintingDemo Total price = 4 2025-10-19 18:29:53,694 INFO 169232 [t=Thread-3] demo.PrintingDemo Total price = 45 2025-10-19 18:29:53,720 INFO 169232 [t=Thread-1] demo.PrintingDemo Price of item = 26 2025-10-19 18:29:53,797 INFO 169232 [t=Thread-3] demo.PrintingDemo Price of item = 27 2025-10-19 18:29:53,801 INFO 169232 [t=Thread-2] demo.PrintingDemo Price of item = 89 2025-10-19 18:29:53,847 INFO 169232 [t=Thread-2] demo.PrintingDemo Items in order = [5] 2025-10-19 18:29:53,895 INFO 169232 [t=Thread-1] demo.PrintingDemo Items in order = [2] 2025-10-19 18:29:53,919 INFO 169232 [t=Thread-1] demo.PrintingDemo Total price = 52 2025-10-19 18:29:53,970 INFO 169232 [t=Thread-3] demo.PrintingDemo Items in order = [2] 2025-10-19 18:29:53,990 INFO 169232 [t=Thread-2] demo.PrintingDemo Total price = 445 2025-10-19 18:29:54,057 INFO 169232 [t=Thread-1] demo.PrintingDemo Price of item = 47 2025-10-19 18:29:54,109 INFO 169232 [t=Thread-1] demo.PrintingDemo Items in order = [4] 2025-10-19 18:29:54,163 INFO 169232 [t=Thread-3] demo.PrintingDemo Total price = 54 2025-10-19 18:29:54,298 INFO 169232 [t=Thread-1] demo.PrintingDemo Total price = 188

אפילו אם נסנן לפי מזהה תהליך = Thread-1…

2025-10-19 18:29:53,484 INFO 169232 [t=Thread-1] demo.PrintingDemo Price of item = 26 2025-10-19 18:29:53,545 INFO 169232 [t=Thread-1] demo.PrintingDemo Items in order = [3] 2025-10-19 18:29:53,631 INFO 169232 [t=Thread-1] demo.PrintingDemo Total price = 78 2025-10-19 18:29:53,720 INFO 169232 [t=Thread-1] demo.PrintingDemo Price of item = 26 2025-10-19 18:29:53,895 INFO 169232 [t=Thread-1] demo.PrintingDemo Items in order = [2] 2025-10-19 18:29:53,919 INFO 169232 [t=Thread-1] demo.PrintingDemo Total price = 52 2025-10-19 18:29:54,057 INFO 169232 [t=Thread-1] demo.PrintingDemo Price of item = 47 2025-10-19 18:29:54,109 INFO 169232 [t=Thread-1] demo.PrintingDemo Items in order = [4] 2025-10-19 18:29:54,298 INFO 169232 [t=Thread-1] demo.PrintingDemo Total price = 188

אותו תהליך כעת מטפל במספר הרצות לא קשורות. סינון לפי מזהה תהליך או PID מפיק כעת סיפורים מעורבים.

בשלב זה, הניסיון לקבץ לוגים ביעילות בדרך זו הופך למייגע – מה שאומר שאנו מבזבזים זמן יקר.

לאן זה מוביל אותנו

בשלב זה, הלוגים נכונים מבחינה טכנית, מעוצבים היטב, ועדיין אינם שלמים. הם מתארים אירועים, אך לא ביצועים. הם מספרים לנו מה קרה — אבל לא לאיזו עלילה השתייכו אותם אירועים.

מה הלאה

במקום לסחוט עוד משמעות משרשורים וחותמות זמן, אנחנו צריכים שלוגים יזכרו את ההקשר.

בחלק הבא, נבחן כיצד לצרף הקשר משתמש ללוגים מבלי להעביר מזהים דרך כל מתודה:

→ חלק 2: הקשר משתמש מבלי לשבור את העיצוב שלך

ומאוחר יותר, כאשר משתמשים אינם קיימים ותהליכונים אינם מספיקים:

→ חלק 3: מזהי קורלציה ועקיבות מקצה לקצה

arrow_circle_right תוכן עניינים

wiktor sztwiertnia

Wiktor Sztwiertnia

מהנדס תוכנה בכיר ב-Java

מאמרים קשורים