उच्च सीएफएच लेटेंसी से कर्नेल पैच के साथ ईआरपीएफ / बीसीसी

लिनक्स में कर्नेल और यूजरस्पेस प्रोग्राम डिबगिंग के लिए बहुत सारे उपकरण हैं। उनमें से अधिकांश का प्रदर्शन प्रभाव पड़ता है और आसानी से उत्पादन वातावरण में नहीं चलाया जा सकता है। कुछ साल पहले, eBPF विकसित किया गया था , जो प्रोग्राम को फिर से शुरू करने या कर्नेल मॉड्यूल को लोड करने की आवश्यकता के बिना, कम ओवरहेड के साथ कर्नेल और उपयोगकर्ता स्थान का पता लगाने की क्षमता प्रदान करता है।

अब बहुत सारे टूल हैं जो कि eBPF का उपयोग करते हैं और इस लेख में, हम बताएंगे कि पायथनबीसीसी लाइब्रेरी का उपयोग करके अपने स्वयं के प्रोफाइलिंग टूल को कैसे लिखें। यह लेख उत्पादन के माहौल से एक वास्तविक मुद्दे पर आधारित है। हम आपको समस्या को हल करने के माध्यम से चलेंगे और बताएंगे कि कुछ मामलों में मौजूदा बीसीसी उपकरण कैसे इस्तेमाल किए जा सकते हैं।

सिफ धीमी है

Ceph क्लस्टर में एक नया प्लेटफ़ॉर्म जोड़ा गया था। प्लेटफ़ॉर्म पर कुछ डेटा माइग्रेट करने के बाद, लिखने के अनुरोध के लिए विलंबता अन्य सर्वरों की तुलना में अधिक थी।



इस प्लेटफ़ॉर्म में एक नया कैशिंग वर्चुअल डिवाइस है - bcache, जिसका उपयोग हमने इस क्लस्टर में पहले नहीं किया है - और एक नया कर्नेल - 4.15, जो अभी भी इस क्लस्टर में कहीं और उपयोग नहीं किया गया है। समस्या की जड़ कहीं भी हो सकती है, इसलिए आइए गहराई से देखें।

मेज़बान की जाँच

आइए देखें कि सीफ-ओएसडी प्रक्रिया के अंदर क्या हो रहा है। हम लौ का निर्माण करने के लिए ट्रेसिंग टूल perf और flamescope का उपयोग करते हैं:



जैसा कि हम फ्लेमोग्राफ से देख सकते हैं, fdatasync () ने जेनेरिक_मेक_रेक्वेस्ट () फ़ंक्शन में जैव प्रस्तुत करने में बहुत समय बिताया है। इस प्रकार, हमारी समस्या की जड़ सेफ डेमॉन के बाहर कहीं है। यह एक कर्नेल, bcache या डिस्क समस्या हो सकती है। Iostat आउटपुट ने bcache उपकरणों के लिए उच्च विलंबता दिखाई।

एक और संदेहास्पद खोज यह है कि सिस्टम-यूडव्ड डेमॉन सीपीयू का उपभोग कर रहा है; कई CPU पर 20%। यह अजीब व्यवहार है, इसलिए हमें यह पता लगाना होगा कि क्या हो रहा है। चूंकि systemd-udevd uevents के साथ काम करता है, हमें सिस्टम में कोई uevents हैं, यह पता लगाने के लिए udvadm मॉनिटर का उपयोग करना होगा। जाँच करने के बाद, हमने देखा कि सिस्टम में प्रत्येक ब्लॉक डिवाइस के लिए बहुत सारे "परिवर्तन" uevents उत्पन्न हो रहे थे।

यह असामान्य है, इसलिए हम यह पता लगाने जा रहे हैं कि इन सभी uevents को क्या भेजा जा रहा है।

बीसीसी टूलकिट का उपयोग करना

जैसा कि हम पहले से ही जानते हैं, कर्नेल (और सेफ डेमन) जेनेरिक_मेक_रेक्स्ट () कार्यों को करने में बहुत समय व्यतीत कर रहा है। चलो बीसीसी टूलकिट से फंगलसिटी का उपयोग करके इसकी विलंबता को मापते हैं , बस यह सुनिश्चित करने के लिए कि हम सही रास्ते पर हैं। हम 1 सेकंड के अंतराल (-i) में ceph डेमन के PID (-p तर्क) का पता लगाएंगे और मिलीसेकंड (-m) में विलंबता को प्रिंट करेंगे।



यह फ़ंक्शन आमतौर पर बहुत तेजी से काम करता है। यह सब डिवाइस चालक की कतार में जैव संरचना को प्रस्तुत करता है।

Bcache एक जटिल उपकरण है; वास्तव में, इसमें 3 डिवाइस शामिल हैं: एक बैकिंग डिवाइस, जो हमारे मामले में एक धीमी गति से HDD है; एक कैशिंग डिवाइस, जो NVMe ड्राइव का विभाजन है; और एक bcache वर्चुअल डिवाइस, जिसका उपयोग एप्लिकेशन द्वारा किया जाता है। हम जानते हैं कि सबमिशन धीमा है, लेकिन किस डिवाइस के लिए? यह कुछ ऐसा है जिसे हम थोड़ा बाद में देखेंगे।

अभी के लिए, हम जानते हैं कि uevents ceph daemons में समस्याएँ पैदा करते हैं और हमें uevents को ट्रिगर करने वाले सॉफ़्टवेयर को ढूंढना होगा। यह खोजने के लिए आसान नहीं है कि क्या uevents उत्पन्न होते हैं। हम मानते हैं कि यह सॉफ्टवेयर है जो केवल समय-समय पर चलता है। यह देखने के लिए कि सिस्टम पर क्या निष्पादित किया जा रहा है, हम बीसीसी टूलकिट से एग्ज़ानस्पॉप का उपयोग करते हैं। हम इसे चला सकते हैं और किसी फाइल में रीडायरेक्ट कर सकते हैं।

उदाहरण के लिए:

/usr/share/bcc/tools/execsnoop | tee ./execdump 

हम यहाँ पर पूर्ण क्रियान्वयन आउटपुट नहीं देंगे, लेकिन एक दिलचस्प स्ट्रिंग जो हमें मिली थी वह थी:

 sh 1764905 5802 0 sudo arcconf getconfig 1 AD | grep Temperature | awk -F '[:/]' '{print $2}' | sed 's/^ \([0-9]*\) C.*/\1/' 

तीसरा कॉलम प्रक्रिया का PPID है। हमने चेक किया कि 5802 क्या था और देखा कि यह हमारे मॉनीटरिंग डेमन थ्रेड्स में से एक है। मॉनिटरिंग सिस्टम कॉन्फ़िगरेशन को देखते हुए, हमें एक दोषपूर्ण पैरामीटर मिला। एचबीए तापमान को हर 30 सेकंड में पुनर्प्राप्त किया जा रहा था, जो कि बहुत बार होता है। चेक अंतराल को और अधिक उचित मूल्य में बदलने के बाद, हमने देखा कि हमारे सीएफएच विलंबता ने अन्य प्लेटफार्मों से मेल खाया।

लेकिन हम अभी भी नहीं जानते हैं कि bcache विलंबता अधिक क्यों थी। हमने एक ही कॉन्फ़िगरेशन के साथ एक परीक्षण प्लेटफ़ॉर्म स्थापित किया और udvadm ट्रिगर कमांड के साथ udev को ट्रिगर करते हुए bcache डिवाइस पर fio के साथ समस्या को पुन: उत्पन्न करने का प्रयास किया।

लेखन BCC- आधारित उपकरण

हम यहां जो करने जा रहे हैं वह एक सरल टूल है जो सबसे धीमी जेनेरिक_मेक_रेक्वेस्ट () कॉल को ट्रेस करता है और उस डिस्क का नाम प्रिंट करता है जिसे फ़ंक्शन के लिए बुलाया गया था।

योजना सरल है:

• जेनेरिक_मेक_रेक्वेस्ट () पर रजिस्टर करें
  
  • फ़ंक्शन के तर्क से उपलब्ध डिस्क नाम को सहेजें
  • वर्तमान टाइमस्टैम्प सहेजें
• जेनरिक_मेक_रेक्वेस्ट () रिटर्न स्टेटमेंट पर क्रेटप्रोब रजिस्टर करें:
  
  • वर्तमान टाइमस्टैम्प को पुनः प्राप्त करें
  • पहले से सहेजे गए टाइमस्टैम्प्स देखें और उनकी तुलना करेंट से करें
  • यदि परिणाम थ्रेशोल्ड से अधिक है, तो पहले से सहेजे गए डिस्क नामों को देखें और उन्हें अतिरिक्त जानकारी के साथ टर्मिनल पर प्रिंट करें

Kprobes और kretprobes रनटाइम में फ़ंक्शन के कोड को बदलने के लिए ब्रेकप्वाइंट का उपयोग करते हैं। आप प्रलेखन और साथ ही इस पर एक अच्छा लेख पा सकते हैं। यदि आप विभिन्न BCC टूल के लिए कोड पर एक नज़र डालते हैं, तो आप देखेंगे कि इन सभी में एक समान संरचना है। हम तर्क पार्स करना छोड़ देंगे और बीपीएफ कार्यक्रम पर ही ध्यान केंद्रित करेंगे।

हमारे कार्यक्रम के पाठ को अजगर में परिभाषित किया जाएगा:

 bpf_text = “”” # Here will be the bpf program code “”” 

BPF प्रोग्राम विभिन्न कार्यों के बीच डेटा साझा करने के लिए हैशमैप का उपयोग करता है। हम मूल्य के रूप में एक महत्वपूर्ण और स्व-परिभाषित संरचना के रूप में पीआईडी ​​का उपयोग करेंगे।

 struct data_t { u64 pid; u64 ts; char comm[TASK_COMM_LEN]; u64 lat; char disk[DISK_NAME_LEN]; }; BPF_HASH(p, u64, struct data_t); BPF_PERF_OUTPUT(events); 

यहाँ हम एक U64 कुंजी प्रकार और एक डेटा data_t मान प्रकार के साथ एक हैशमैप p दर्ज करते हैं। यह नक्शा हमारे बीपीएफ कार्यक्रम के संदर्भ से सुलभ है। BPF_PERF_OUTPUT मैक्रो ईवेंट नामक एक अन्य मानचित्र पंजीकृत करता है, जिसका उपयोग उपयोगकर्ताओं को डेटा पुश करने के लिए किया जाता है।

फ़ंक्शन कॉल और उसकी वापसी के बीच या एक फ़ंक्शन कॉल और किसी अन्य के बीच विलंबता को मापते समय, आपको यह सुनिश्चित करना होगा कि आपके द्वारा सहेजा गया डेटा और एक्सेस बाद में उसी संदर्भ से संबंधित है। दूसरे शब्दों में, आपको समान फ़ंक्शन के किसी भी अन्य समानांतर निष्पादन के बारे में पता होना चाहिए। एक प्रक्रिया के फ़ंक्शन कॉल और किसी अन्य प्रक्रिया से समान फ़ंक्शन के रिटर्न के बीच विलंबता का पता लगाना संभव है, लेकिन यह हमारी मदद नहीं करता है। एक अच्छा उदाहरण है बायोलैटेंसी टूल, जहां पॉइंटर टू स्ट्रक्चर रिक्वेस्ट का इस्तेमाल हैशम की के रूप में किया जाता है।

इसके बाद, हमें एक कोड लिखना होगा, जो कि एक kprobe तंत्र के माध्यम से फ़ंक्शन कॉल पर निष्पादित किया जाएगा:

 void start(struct pt_regs *ctx, struct bio *bio) { u64 pid = bpf_get_current_pid_tgid(); struct data_t data = {}; u64 ts = bpf_ktime_get_ns(); data.pid = pid; data.ts = ts; bpf_probe_read_str(&data.disk, sizeof(data.disk), (void*)bio->bi_disk->disk_name); p.update(&pid, &data); } 

हमारे पास पहला जेनेरिक_मेके_रेक्वेस्ट () तर्क है जो हमारे फ़ंक्शन का दूसरा तर्क है। फिर हम नैनो-सेकंड में पीआईडी ​​और वर्तमान टाइमस्टैम्प प्राप्त करते हैं और इसे नए आवंटित किए गए स्ट्रक्चर डेटा_टी डेटा में लिखते हैं । हमें जैव संरचना से डिस्क का नाम मिलता है, जिसे जेनेरिक_मेक_रेक्वेस्ट () में भेज दिया जाता है, और इसे हमारे डेटा में सहेज दिया जाता है। अंतिम चरण हमारे द्वारा पहले वर्णित हैशमाप में एक प्रविष्टि जोड़ना है।

इस कार्य को जेनेरिक_मेक_रेक्वेस्ट () रिटर्न पर निष्पादित किया जाएगा:

 void stop(struct pt_regs *ctx) { u64 pid = bpf_get_current_pid_tgid(); u64 ts = bpf_ktime_get_ns(); struct data_t* data = p.lookup(&pid); if (data != 0 && data->ts > 0) { bpf_get_current_comm(&data->comm, sizeof(data->comm)); data->lat = (ts - data->ts)/1000; if (data->lat > MIN_US) { FACTOR data->pid >>= 32; events.perf_submit(ctx, data, sizeof(struct data_t)); } p.delete(&pid); } } 

हम पिछले आउटपुट से पीआईडी ​​और टाइमस्टैम्प प्राप्त करते हैं और उस मान के लिए हैशमैप देखते हैं जहां कुंजी == वर्तमान पीआईडी ​​है । यदि यह पाया जाता है, तो हम चल रहे प्रक्रिया का नाम लेते हैं और इसे डेटा संरचना में जोड़ते हैं। हम डेटा के साथ क्या करते हैं-> यहाँ pid हमें थ्रेड ग्रुप id देता है। पहले कहा जाने वाला bpf_get_current_pid_tgid () फ़ंक्शन समान 64-बिट मान में प्रक्रिया का थ्रेड GID और PID लौटाता है।

हमें हर थ्रेड आईडी में कोई दिलचस्पी नहीं है, लेकिन हम मुख्य थ्रेड के PID को जानना चाहते हैं। यह जांचने के बाद कि विलंबता दहलीज से ऊपर है, हम अपने डेटा संरचना को इवेंट मैप के माध्यम से यूजरस्पेस में जमा करते हैं, फिर अंत में हैशमाप एंट्री को हटा दें।

हमारी पाइथन लिपि में, हमें उस सीमा के अनुसार MIN_US और FACTOR को बदलना होगा जिसे हम अपने परिणाम में देखना चाहते हैं और उस समय की इकाई के अनुसार:

 bpf_text = bpf_text.replace('MIN_US',str(min_usec)) if args.milliseconds: bpf_text = bpf_text.replace('FACTOR','data->lat /= 1000;') label = "msec" else: bpf_text = bpf_text.replace('FACTOR','') label = "usec" 

फिर हमें BPF () मैक्रो और रजिस्टर प्रोब के साथ BPF प्रोग्राम तैयार करना है:

 b = BPF(text=bpf_text) b.attach_kprobe(event="generic_make_request",fn_name="start") b.attach_kretprobe(event="generic_make_request",fn_name="stop") 

BPF प्रोग्राम के डेटा को पढ़ने के लिए भी हमें अपनी स्क्रिप्ट में उसी संरचना को डेटा data_t के रूप में परिभाषित करना होगा:

 TASK_COMM_LEN = 16 # linux/sched.h DISK_NAME_LEN = 32 # linux/genhd.h class Data(ct.Structure): _fields_ = [("pid", ct.c_ulonglong), ("ts", ct.c_ulonglong), ("comm", ct.c_char * TASK_COMM_LEN), ("lat", ct.c_ulonglong), ("disk",ct.c_char * DISK_NAME_LEN)] 

अंतिम चरण वह डेटा प्रिंट करना है जिसे हम चाहते हैं:

 def print_event(cpu, data, size): global start event = ct.cast(data, ct.POINTER(Data)).contents if start == 0: start = event.ts time_s = (float(event.ts - start)) / 1000000000 print("%-18.9f %-16s %-6d %-1s %s %s" % (time_s, event.comm, event.pid, event.lat, label, event.disk)) b["events"].open_perf_buffer(print_event) # format output start = 0 while 1: try: b.perf_buffer_poll() except KeyboardInterrupt: exit() 

पूरा स्क्रिप्ट GitHub पर उपलब्ध है । चलो स्क्रिप्ट चलाते हैं और udev घटनाओं को ट्रिगर करते हैं जबकि fio एक bcache डिवाइस को लिखते हैं:



सफलता! अब हम देखते हैं कि bcache के लिए उच्च विलंबता जैसा जो दिखता था, वह वास्तव में अपने बैकिंग डिवाइस के लिए सामान्य-सेकंड (request) है।

गिरी में खोदो

अनुरोध सबमिट करते समय क्या होता है? हम देखते हैं कि अनुरोध खाते से शुरू होने से पहले एक विलंबता स्पाइक भी हुआ था। यह समस्या के दौरान या तो बायोसैट या बायोलाटेंसी बीसीसी स्क्रिप्ट को चलाकर आसानी से जांचा जा सकता है, जो अकाउंटिंग रिक्वेस्ट स्टार्ट पर आधारित है, इसलिए न तो टूल डिस्क की समस्या को दिखाएगा।

यदि हम generic_make_request () पर एक नज़र डालते हैं , तो हम देखते हैं कि लेखांकन शुरू होने से पहले दो कार्य चल रहे हैं। पहला है जेनेरिक_मेके_रेक्वेस्ट_चेक () , जो कि लाइट है और डिवाइस सेटिंग्स आदि के अनुसार बायो चेक करता है। दूसरा blk_queue_enter () है , जिसमें एक wa_event_interruptible () कॉल है:

 ret = wait_event_interruptible(q->mq_freeze_wq, (atomic_read(&q->mq_freeze_depth) == 0 && (preempt || !blk_queue_preempt_only(q))) || blk_queue_dying(q)); 

यहाँ कर्नेल का इंतजार तब तक किया जाता है जब तक कि कतार अक्षम न हो। चलो blk_queue_enter () की विलंबता को मापते हैं:

 ~# /usr/share/bcc/tools/funclatency blk_queue_enter -i 1 -m Tracing 1 functions for "blk_queue_enter"... Hit Ctrl-C to end. msecs : count distribution 0 -> 1 : 341 |****************************************| msecs : count distribution 0 -> 1 : 316 |****************************************| msecs : count distribution 0 -> 1 : 255 |****************************************| 2 -> 3 : 0 | | 4 -> 7 : 0 | | 8 -> 15 : 1 | | 

ऐसा लगता है कि हम करीब हैं। कतार को फ्रीज / अनफ्रेंड करने के लिए उपयोग किए जाने वाले कार्य blk_mq_freeze_queue और blk_mq_unfreeze_queue हैं । वे कतार सेटिंग्स बदलने के लिए उपयोग किए जाते हैं, जो वर्तमान में उड़ान में io अनुरोधों को प्रभावित कर सकते हैं। जब blk_mq_freeze_queue () कहा जाता है, q-> mq_freeze_depth को blk_freeze_queue_start () में बढ़ाया जाता है । उसके बाद, कर्नेल blk_mq_freeze_queue_wait () में कतार के खाली होने की प्रतीक्षा करता है।

यह प्रतीक्षा समय डिस्क विलंबता के बराबर है, क्योंकि कर्नेल को समाप्त करने के लिए सभी io संचालन के लिए इंतजार करना पड़ता है। जब कतार खाली होती है, तो परिवर्तन किए जा सकते हैं। अंतिम चरण blk_mq_unfreeze_queue () को कॉल करना है , जो फ्रीज_डेप काउंटर को घटाता है ।

अब हम इस मुद्दे को ठीक करने के लिए पर्याप्त जानते हैं। Udvadm ट्रिगर कमांड ब्लॉक डिवाइसेस के लिए सेटिंग्स को बदलता है। उन सेटिंग्स को udv नियमों में वर्णित किया गया है। हम यह पता लगा सकते हैं कि किन सेटिंग्स को क्यूसेफ के माध्यम से बदलकर या कर्नेल स्रोत कोड को देखकर फ्रीज कर सकते हैं। वैकल्पिक रूप से, हम BCC टूलकिट से टकराने के लिए कर्नेल और उपयोगकर्ता स्टैक को हर blk_freeze_leue के लिए कॉल कर सकते हैं:

 ~# /usr/share/bcc/tools/trace blk_freeze_queue -K -U PID TID COMM FUNC 3809642 3809642 systemd-udevd blk_freeze_queue blk_freeze_queue+0x1 [kernel] elevator_switch+0x29 [kernel] elv_iosched_store+0x197 [kernel] queue_attr_store+0x5c [kernel] sysfs_kf_write+0x3c [kernel] kernfs_fop_write+0x125 [kernel] __vfs_write+0x1b [kernel] vfs_write+0xb8 [kernel] sys_write+0x55 [kernel] do_syscall_64+0x73 [kernel] entry_SYSCALL_64_after_hwframe+0x3d [kernel] __write_nocancel+0x7 [libc-2.23.so] [unknown] 3809631 3809631 systemd-udevd blk_freeze_queue blk_freeze_queue+0x1 [kernel] queue_requests_store+0xb6 [kernel] queue_attr_store+0x5c [kernel] sysfs_kf_write+0x3c [kernel] kernfs_fop_write+0x125 [kernel] __vfs_write+0x1b [kernel] vfs_write+0xb8 [kernel] sys_write+0x55 [kernel] do_syscall_64+0x73 [kernel] entry_SYSCALL_64_after_hwframe+0x3d [kernel] __write_nocancel+0x7 [libc-2.23.so] [unknown] 

Udev नियमों में अक्सर बदलाव नहीं होता है, इसलिए कुछ मापदंडों के लिए पहले से ही मौजूद मानों को असाइन करने से एप्लिकेशन के लिए विलंबता प्रस्तुत करने में स्पाइक होता है। जब डिवाइस के कॉन्फ़िगरेशन में कोई परिवर्तन नहीं होता है (कोई डिवाइस संलग्न या अलग नहीं है) तो निश्चित रूप से udv ईवेंट उत्पन्न करना एक अच्छा अभ्यास नहीं है। फिर भी, यदि ऐसा करने का कोई कारण नहीं है, तो हम कर्नेल को कतार को जमने से रोक सकते हैं। तीन छोटे-छोटे मुद्दे ठीक करते हैं।

निष्कर्ष

eBPF अत्यधिक लचीला और शक्तिशाली उपकरण है। इस लेख में, हमने केवल एक ही मामले को देखा और जो इसमें सक्षम है उसका थोड़ा सा प्रदर्शन किया। यदि आप BCC- आधारित टूल को विकसित करने में रुचि रखते हैं, तो आपको आधिकारिक ट्यूटोरियल पर एक नज़र डालनी चाहिए , जो इसकी मूलभूत अवधारणाओं का वर्णन करता है।

प्रोफाइलिंग और डीबगिंग के लिए अन्य दिलचस्प ईजीपीएफ-आधारित टूल भी उपलब्ध हैं। उनमें से एक bpftrace है , जो आपको एक अजीब तरह की भाषा में शक्तिशाली ऑनलिनर्स और छोटे प्रोग्राम लिखने देता है। एक और एक है ebpf_exporter , जो अपने शानदार दृश्य और चेतावनी क्षमताओं के साथ अपने प्रोमेथियस सर्वर के लिए निम्न-स्तरीय उच्च-रिज़ॉल्यूशन मैट्रिक्स एकत्र कर सकता है।