פתרון בעיות שקשורות לזמן אחזור בספריית הלקוח של Java

מבוא

אם באפליקציה יש זמן אחזור גבוה מהרגיל, תפוקה נמוכה או פסק זמן עם לקוח Java Datastore, יכול להיות שהבעיה נובעת מהגדרת gRPC בצד הלקוח ולא מהקצה העורפי של Firestore/Datastore. המדריך הזה יעזור לכם לאבחן ולפתור בעיות נפוצות שקשורות להגבלת קצב העברת הנתונים בצד הלקוח, להגדרות לא תקינות של מאגר הערוצים ולשינויים תכופים מדי בערוצים.

אבחון

כשמשתמשים בלקוחות Java, חשוב להפעיל רישום מפורט של gRPC ו-gax-java כדי לעקוב אחרי הדינמיקה של מאגר הערוצים, לאבחן הגבלת קצב, לפתור בעיות בשימוש חוזר בחיבורים או לזהות תחלופה מוגזמת של ערוצים.

הפעלת רישום ביומן ללקוחות Java

כדי להפעיל רישום מפורט ביומן, משנים את הקובץ logging.properties באופן הבא:

## This tracks the lifecycle events of each grpc channel 
io.grpc.ChannelLogger.level=FINEST
## Tracks channel pool events(resizing, shrinking) from GAX level
com.google.api.gax.grpc.ChannelPool.level=FINEST

בנוסף, צריך לעדכן את רמת רישום הפלט ביומן בקובץ logging.properties כדי לתעד את היומנים האלה:


# This could be changed to a file or other log output
handlers=java.util.logging.ConsoleHandler
java.util.logging.ConsoleHandler.level=FINEST
java.util.logging.ConsoleHandler.formatter=java.util.logging.SimpleFormatter

שימוש בתצורה

אפשר להחיל קובץ logging.properties באחת משתי דרכים:

1. דרך מאפיין מערכת של JVM

מוסיפים את הארגומנט הזה כשמפעילים את אפליקציית Java:

-Djava.util.logging.config.file=/path/to/logging.properties

2. טעינה באמצעות תוכנה

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

LogManager logManager = LogManager.getLogManager();
  try (final InputStream is = Main.class.getResourceAsStream("/logging.properties")) {
logManager.readConfiguration(is);
}

דוגמה לרישום ביומן

אחרי שמפעילים רישום מפורט ביומן, מוצגות הודעות משולבות מ-com.google.api.gax.grpc.ChannelPool ומ-io.grpc.ChannelLogger:

ערוצים שהוקצו להם פחות מדי משאבים, מה שהוביל להרחבת מאגר הערוצים:

09:15:30.123 [pool-1-thread-1] DEBUG com.google.api.gax.grpc.ChannelPool - Detected throughput peak of 40, expanding channel pool size: 4 -> 6. 
09:15:30.124 [grpc-nio-worker-ELG-1-5] DEBUG io.grpc.ChannelLogger - [Channel<5>: (datastore.googleapis.com:443)] Entering IDLE state 
09:15:30.124 [grpc-nio-worker-ELG-1-5] DEBUG io.grpc.ChannelLogger - [Channel<6>: (datastore.googleapis.com:443)] Entering IDLE state 
09:15:30.125 [grpc-nio-worker-ELG-1-5] TRACE io.grpc.ChannelLogger - [Channel<5>: (datastore.googleapis.com:443)] newCall() called 
09:15:30.126 [grpc-nio-worker-ELG-1-5] DEBUG io.grpc.ChannelLogger - [Channel<5>: (datastore.googleapis.com:443)] Entering CONNECTING state 09:15:30.127 [grpc-nio-worker-ELG-1-5] DEBUG io.grpc.ChannelLogger - [Channel<5>: (datastore.googleapis.com:443)] Entering READY state with picker: Picker{result=PickResult{subchannel=Subchannel<7>: (datastore.googleapis.com:443), streamTracerFactory=null, status=Status{code=OK, description=null, cause=null}, drop=false, authority-override=null}} 
09:15:31.201 [grpc-nio-worker-ELG-1-6] TRACE io.grpc.ChannelLogger - [Channel<6>: (datastore.googleapis.com:443)] newCall() called 
09:15:31.202 [grpc-nio-worker-ELG-1-6] DEBUG io.grpc.ChannelLogger - [Channel<6>: (datastore.googleapis.com:443)] Entering CONNECTING state 09:15:31.203 [grpc-nio-worker-ELG-1-6] DEBUG io.grpc.ChannelLogger - [Channel<6>: (datastore.googleapis.com:443)] Entering READY state with picker: Picker{result=PickResult{subchannel=Subchannel<8>: (datastore.googleapis.com:443), streamTracerFactory=null, status=Status{code=OK, description=null, cause=null}, drop=false, authority-override=null}}

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

09:13:59.609 [grpc-nio-worker-ELG-1-4] DEBUG io.grpc.ChannelLogger - [Channel<21>: (datastore.googleapis.com:443)] Entering READY state with picker: Picker{result=PickResult{subchannel=Subchannel<23>: (datastore.googleapis.com:443), streamTracerFactory=null, status=Status{code=OK, description=null, cause=null}, drop=false, authority-override=null}}
09:14:01.998 [pool-1-thread-1] DEBUG com.google.api.gax.grpc.ChannelPool - Detected throughput drop to 0, shrinking channel pool size: 8 -> 6.
09:14:01.999 [pool-1-thread-1] TRACE io.grpc.ChannelLogger - [Channel<13>: (datastore.googleapis.com:443)] shutdown() called
09:14:01.999 [pool-1-thread-1] DEBUG io.grpc.ChannelLogger - [Channel<13>: (datastore.googleapis.com:443)] Entering SHUTDOWN state
09:14:01.999 [pool-1-thread-1] DEBUG io.grpc.ChannelLogger - [Channel<13>: (datastore.googleapis.com:443)] Terminated
09:14:01.999 [pool-1-thread-1] TRACE io.grpc.ChannelLogger - [Channel<15>: (datastore.googleapis.com:443)] shutdown() called
09:14:01.999 [pool-1-thread-1] DEBUG io.grpc.ChannelLogger - [Channel<15>: (datastore.googleapis.com:443)] Entering SHUTDOWN state
09:14:01.999 [pool-1-thread-1] DEBUG io.grpc.ChannelLogger - [Channel<15>: (datastore.googleapis.com:443)] Terminated

רשומות היומן האלה שימושיות למטרות הבאות:

  1. מעקב אחרי החלטות לגבי שינוי הגודל של הערוץ
  2. זיהוי של שימוש חוזר בערוץ לעומת נטישה
  3. זיהוי בעיות בקישוריות של התחבורה

פירוש יומנים לאבחון סימפטומים

כשמנסים לפתור בעיות בביצועים כמו זמן אחזור גבוה או שגיאות, כדאי להתחיל בהפעלת הרישום ביומן עבור com.google.api.gax.grpc.ChannelPool ו-io.grpc.ChannelLogger. לאחר מכן, משווים בין הסימפטומים שאתם רואים לבין התרחישים הנפוצים במדריך הזה כדי לפרש את היומנים ולמצוא פתרון.

תסמין 1: זמן אחזור גבוה בהפעלה או במהלך עליות חדות בתנועת הגולשים

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

סיבה אפשרית

השהייה הזו קורית בדרך כלל כשמאגר הערוצים שלכם לא מספיק גדול. כל ערוץ gRPC יכול לטפל במספר מוגבל של בקשות בו-זמניות (100 מוגבל על ידי Google Middleware). אחרי שמגיעים למגבלה הזו, בקשות RPC חדשות מתווספות לתור בצד הלקוח וממתינות למשבצת פנויה. התור הזה הוא המקור העיקרי לזמן האחזור.

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

יומנים שכדאי לבדוק

מחפשים יומנים שמציינים שהמאגר של הערוצים מתרחב. זו הראיה העיקרית לכך שהלקוח מגיב לשיא תנועה שחרג מהקיבולת הנוכחית שלו.

יומן הרחבת מאגר הערוצים:

[pool-1-thread-1] DEBUG com.google.api.gax.grpc.ChannelPool - Detected throughput peak of 40, expanding channel pool size: 4 -> 6.

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

איך פותרים את הבעיה

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

הגדלה של initialChannelCount (זמן אחזור גבוה בהפעלה):

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

כדי למצוא את הערך הנכון לאפליקציה, צריך:

  1. מפעילים את רישום היומנים ברמה FINEST עבור com.google.api.gax.grpc.ChannelPool.
  2. מריצים את האפליקציה תחת עומס עבודה טיפוסי או עלייה חדה בתעבורה.
  3. בודקים את יומני ההרחבה של מאגר הערוצים כדי לראות מה הגודל שבו המאגר מתייצב.

לדוגמה, אם אתם רואים יומנים כאלה:
[pool-1-thread-1] DEBUG com.google.api.gax.grpc.ChannelPool - Detected throughput peak of 80, expanding channel pool size: 4 -> 6.

ואז, דקה לאחר מכן, מופיעים היומנים:

[pool-1-thread-1] DEBUG com.google.api.gax.grpc.ChannelPool - Detected throughput peak of 95, expanding channel pool size: 6 -> 8.

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

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

עלייה minChannelCount (קפיצות בתנועה):

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

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

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

עלייה maxChannelCount (קפיצות בתנועה):

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

תסמין 2: פסק זמן לסירוגין או כשלים ב-RPC

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

סיבה אפשרית: חוסר יציבות ברשת

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

יומנים שכדאי לבדוק

היומן הכי חשוב לאבחון בעיות ברשת הוא TRANSIENT_FAILURE.

  • יומן של כשלים זמניים:
[grpc-nio-worker-ELG-1-7] DEBUG io.grpc.ChannelLogger - [Channel<9>: (datastore.googleapis.com:443)] Entering TRANSIENT_FAILURE state
  • הסבר: הרישום הזה ביומן הוא נורת אזהרה משמעותית שמצביעה על כך שהערוץ איבד את החיבור שלו. יכול להיות ששיבוש חד-פעמי ומבודד הוא רק תקלה קלה ברשת. עם זאת, אם ההודעות האלה מופיעות לעיתים קרובות או אם ערוץ נתקע במצב הזה, זה מצביע על בעיה משמעותית בבסיס.

איך פותרים את הבעיה

בדיקת סביבת הרשת בודקים אם יש בעיות בחומות אש, בשרתי proxy, בנתבים או בחוסר יציבות כללי ברשת בין האפליקציה לבין datastore.googleapis.com.

תיאור הבעיה 3: זמן אחזור ארוך עם יותר מ-20,000 בקשות בו-זמניות לכל לקוח

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

סיבה אפשרית

הלקוח סובל מרוויה של הערוץ כי מאגר הערוצים הגיע לmaxChannelCount שהוגדר לו. כברירת מחדל, המאגר מוגדר עם מגבלה של 200 ערוצים. מכיוון שכל ערוץ gRPC יכול לטפל בעד 100 בקשות בו-זמנית, המגבלה הזו מושגת רק כשמופע לקוח יחיד מעבד בערך 20,000 בקשות בו-זמנית.

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

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

יומנים שכדאי לבדוק

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

  • יומנים: תוכלו לראות יומנים קודמים של הרחבת המאגר. בהגדרות ברירת המחדל, יומן ההרחבה האחרון שיוצג לפני העלייה החדה בזמן האחזור יהיה זה שבו המאגר מגיע ל-200 ערוצים:
[pool-1-thread-1] DEBUG com.google.api.gax.grpc.ChannelPool - ... expanding channel pool size: 198 -> 200.
  • אינדיקטור: במהלך תקופת זמן האחזור הגבוה, לא יופיעו עוד יומני רישום של 'הגדלת מספר הערוצים'. היעדר היומנים האלה, בשילוב עם זמן האחזור הגבוה, הוא אינדיקטור חזק לכך שהגעתם למגבלה של maxChannelCount.

איך פותרים את הבעיה

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

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

נספח

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

הסבר על מצבי הערוץ

המצבים הבאים של הערוץ יכולים להופיע ביומנים, ולספק תובנות לגבי התנהגות החיבור:

מדינה תיאור
IDLE הערוץ נוצר אבל אין בו חיבורים פעילים או RPC. המערכת ממתינה לתנועה.
מתבצע חיבור הערוץ מנסה באופן פעיל ליצור העברה (חיבור) חדשה ברשת לשרת gRPC.
READY הערוץ כולל העברה מבוססת ותקינה, ומוכן לשליחת בקשות RPC.
TRANSIENT_FAILURE התרחש כשל בערוץ שאפשר לשחזר (למשל, תקלה זמנית ברשת, השרת לא זמין באופן זמני). המכשיר ינסה להתחבר מחדש באופן אוטומטי.
SHUTDOWN הערוץ נסגר, או באופן ידני (למשל, בוצעה קריאה ל-shutdown()) או בגלל פסק זמן של חוסר פעילות. אי אפשר ליזום קריאות RPC חדשות.

טיפים

  • אם אתם משתמשים במסגרת רישום מובנה ביומן כמו SLF4J או Logback, אתם צריכים להגדיר רמות יומן מקבילות ב-logback.xml או בקובצי הגדרות אחרים של כלי רישום. רמות java.util.logging ימופו על ידי חזית הרישום.