👨‍👩‍👧 👩‍⚕️ 👩‍❤️‍👩 इत्र और लौ 👩🏻‍🔬 🚵🏻 🤘🏻

ऑपरेटिंग सिस्टम के प्रदर्शन में सुधार और बाधाओं को खोजने का विषय काफी लोकप्रियता हासिल कर रहा है। इस लेख में, हम लिनक्स में ब्लॉक स्टैक के उदाहरण का उपयोग करके इन स्थानों को खोजने के लिए एक उपकरण के बारे में बात करेंगे और एक मेजबान के समस्या निवारण के एक मामले में।

उदाहरण 1. परीक्षण

कुछ भी काम नहीं करता

हमारे विभाग में परीक्षण उत्पाद हार्डवेयर पर सिंथेटिक्स है, और बाद में - एप्लिकेशन सॉफ़्टवेयर परीक्षण। हमें परीक्षण के लिए Intel Optane ड्राइव मिली। हमने पहले ही अपने ब्लॉग में Optane ड्राइव का परीक्षण करने के बारे में लिखा था।

डिस्क को एक मानक सर्वर में स्थापित किया गया था जो एक क्लाउड प्रोजेक्ट के तहत अपेक्षाकृत लंबे समय के लिए बनाया गया था।

परीक्षण के दौरान, डिस्क ने अपने आप को सबसे अच्छे तरीके से नहीं दिखाया: परीक्षण के दौरान प्रति 1 स्ट्रीम 1 अनुरोध की गहराई के साथ, 4Kbytes के ब्लॉक में ~ 70Kiops के बारे में। और इसका मतलब है कि प्रतिक्रिया का समय बहुत बड़ा है: प्रति अनुरोध लगभग 13 माइक्रोसेकंड!

यह अजीब है, क्योंकि विनिर्देश "विलंबता - 10 µ पढ़ें" का वादा करता है, और हमें 30% अधिक मिला, अंतर काफी महत्वपूर्ण है। डिस्क को दूसरे प्लेटफ़ॉर्म पर पुन: व्यवस्थित किया गया, एक और "ताज़ा" असेंबली का उपयोग किसी अन्य प्रोजेक्ट में किया गया।

यह काम क्यों करता है?

यह मज़ेदार है, लेकिन नए प्लेटफ़ॉर्म पर ड्राइव को उसी तरह काम करना चाहिए, जैसा उसे करना चाहिए। प्रदर्शन में वृद्धि हुई, विलंबता कम हो गई, सीपीयू प्रति शेल्फ, 1 स्ट्रीम प्रति अनुरोध, 4K बाइट्स ब्लॉक, ~ अनुरोध पर ~ 9 माइक्रोसेकंड पर 106Kiops।

और फिर यह विस्तृत पैरों से परिपूर्ण होने के ~~लिए सेटिंग्स की तुलना~~ करने का समय है। आखिर हमें आश्चर्य होता है कि ऐसा क्यों? पूर्ण के साथ , आप कर सकते हैं:

हार्डवेयर काउंटर रीडिंग लें: निर्देश कॉल की संख्या, कैश मिस, गलत तरीके से भविष्यवाणी की गई शाखाएं आदि। (पीएमयू इवेंट्स)
स्थिर ट्रेडिंग बिंदुओं से जानकारी निकालें, घटनाओं की संख्या
गतिशील अनुरेखण आचरण

सत्यापन के लिए, हमने सीपीयू नमूने का उपयोग किया।

लब्बोलुआब यह है कि पूर्ण एक चल रहे कार्यक्रम के पूरे स्टैक ट्रेस संकलन कर सकते हैं। स्वाभाविक रूप से, रनिंग परफेक्ट पूरे सिस्टम के संचालन में देरी का परिचय देगा। लेकिन हमारे पास ध्वज -F # है , जहां # नमूनाकरण आवृत्ति है, जिसे हर्ट्ज में मापा जाता है।

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

एक आवृत्ति का चयन करते समय, आपको सामान्य ज्ञान और एक चाल द्वारा निर्देशित होने की आवश्यकता होती है - एक भी आवृत्ति सेट करने की कोशिश न करें, ताकि ऐसी स्थिति में न आएं जब इस आवृत्ति के साथ टाइमर पर चलने वाले कुछ काम नमूनों में हो जाते हैं।

एक अन्य बिंदु जो शुरू में भ्रामक है - सॉफ्टवेयर को ध्वज -fno-omit-फ्रेम-पॉइंटर के साथ संकलित किया जाना चाहिए, यदि यह, ज़ाहिर है, संभव है। अन्यथा, फ़ंक्शन नामों के बजाय ट्रेस में, हम ठोस अज्ञात मान देखेंगे। कुछ सॉफ़्टवेयर के लिए, डिबगिंग प्रतीक एक अलग पैकेज के रूप में आते हैं, उदाहरण के लिए, someutil-dbg । यह अनुशंसा की जाती है कि आप उन्हें पूर्ण चलाने से पहले स्थापित करें।

हमने निम्नलिखित क्रियाएं कीं:

Git से fio लिया: //git.kernel.dk/fio.git, टैग fio-3.9
Makefile में CPPFLAGS के लिए -fno -omit-फ़्रेम-पॉइंटर विकल्प
लॉन्च किया गया -j8

perf record -g ~/fio/fio --name=test --rw=randread --bs=4k --ioengine=pvsync2 --filename=/dev/nvme0n1 --direct=1 --hipri --filesize=1G

निशान के ढेर को पकड़ने के लिए -g विकल्प की आवश्यकता होती है।

आप आदेश द्वारा परिणाम देख सकते हैं:

 perf report -g fractal

-G भग्न विकल्प की आवश्यकता है ताकि प्रतिशत इस फ़ंक्शन के साथ नमूनों की संख्या को दर्शाते हैं और पूर्ण द्वारा दिखाए गए कॉलिंग फ़ंक्शन के सापेक्ष हैं, जिनमें से कॉल की संख्या 100% के रूप में ली गई है।

"ताजा बिल्ड" प्लेटफॉर्म पर लंबी फियो कॉल स्टैक के अंत की ओर, हम देखेंगे:

और "पुराने बिल्ड" प्लेटफॉर्म पर:

बहुत बढ़िया! लेकिन मुझे सुंदर लौ चाहिए।

बिल्डिंग फ्लेमग्राम

सुंदर होने के लिए, दो उपकरण हैं:

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

ये उपयोगिताओं सही स्क्रिप्ट> इनपुट के रूप में परिणाम स्वीकार करते हैं।

परिणाम डाउनलोड करें और इसे svg में पाइप के माध्यम से भेजें:

 FlameGraph/stackcollapse-perf.pl ./result | FlameGraph/flamegraph.pl > ./result.svg

एक ब्राउज़र में खोलें और एक क्लिक करने योग्य चित्र का आनंद लें।

आप दूसरी विधि का उपयोग कर सकते हैं:

परिणाम को फ्लेमस्कोप / उदाहरण में जोड़ें /
अजगर को चलाएँ ।/run.py
हम ब्राउज़र के माध्यम से स्थानीय होस्ट के 5000 पोर्ट तक जाते हैं

हम अंत में क्या देखते हैं?

एक अच्छा फियो मतदान में बहुत समय बिताता है:

एक बुरा फियो कहीं भी समय बिताता है, लेकिन मतदान में नहीं:

पहली नज़र में, ऐसा लगता है कि मतदान पुराने होस्ट पर काम नहीं करता है, लेकिन हर जगह 4.15 कर्नेल एक ही विधानसभा के होते हैं और एनवीएम डिस्क पर डिफ़ॉल्ट रूप से मतदान सक्षम होता है। जाँच करें कि मतदान sysfs में सक्षम है या नहीं:

 # cat /sys/class/block/nvme0n1/queue/io_poll 1

परीक्षणों के दौरान, RWF_HIPRI ध्वज के साथ preadv2 कॉल का उपयोग किया जाता है - मतदान कार्य करने के लिए एक आवश्यक शर्त। और, यदि आप लौ ग्राफ (या पूर्ण रिपोर्ट आउटपुट से पिछले स्क्रीनशॉट) का सावधानीपूर्वक अध्ययन करते हैं, तो आप इसे पा सकते हैं, लेकिन इसमें बहुत कम समय लगता है।

दूसरी चीज़ जो दिखाई देती है वह है submit_bio () फ़ंक्शन और io_schedule () कॉल की कमी के लिए अलग-अलग कॉल स्टैक। चलिए submit_bio () के अंतर पर करीब से नज़र डालते हैं।

धीमा प्लेटफ़ॉर्म "पुराना बिल्ड":

फास्ट प्लेटफ़ॉर्म "ताज़ा":

ऐसा लगता है कि एक धीमे मंच पर, अनुरोध डिवाइस पर एक लंबा रास्ता तय करता है, उसी समय कियबर शेड्यूलर में हो रहा है । आप हमारे लेख में I / O शेड्यूलर के बारे में अधिक पढ़ सकते हैं।

एक बार किबर को बंद कर दिया गया था, उसी fio परीक्षण ने लगभग 10 माइक्रोसेकंड की औसत विलंबता दिखाई, जैसा कि कल्पना में कहा गया है। बहुत बढ़िया!

लेकिन दूसरे माइक्रोसेकंड में अंतर कहां से आता है?

और अगर थोड़ा गहरा हो?

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

 perf stat -e cycles,instructions,cache-references,cache-misses,bus-cycles /root/fio/fio --clocksource=cpu --name=test --bs=4k --filename=/dev/nvme0n1p4 --direct=1 --ioengine=pvsync2 --hipri --rw=randread --filesize=4G --loops=10

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

उदाहरण 2. किराने

कुछ गलत हो रहा है

एक वितरित डेटा भंडारण प्रणाली के काम में, आने वाले ट्रैफ़िक में वृद्धि के साथ मेजबान में से एक पर सीपीयू पर लोड में वृद्धि देखी गई। मेजबान सहकर्मी, सहकर्मी हैं, और समान हार्डवेयर और सॉफ्टवेयर हैं।

सीपीयू लोड को देखते हैं:

 ~# pidstat -p 1441734 1 Linux 3.13.0-96-generic (lol) 10/10/2018 _x86_64_ (24 CPU) 09:23:30 PM UID PID %usr %system %guest %CPU CPU Command 09:23:44 PM 0 1441734 23.00 1.00 0.00 24.00 4 ceph-osd 09:23:45 PM 0 1441734 85.00 34.00 0.00 119.00 4 ceph-osd 09:23:46 PM 0 1441734 0.00 130.00 0.00 130.00 4 ceph-osd 09:23:47 PM 0 1441734 121.00 0.00 0.00 121.00 4 ceph-osd 09:23:48 PM 0 1441734 28.00 82.00 0.00 110.00 4 ceph-osd 09:23:49 PM 0 1441734 4.00 13.00 0.00 17.00 4 ceph-osd 09:23:50 PM 0 1441734 1.00 6.00 0.00 7.00 4 ceph-osd

यह समस्या 09:23:46 पर उठी और हम देखते हैं कि यह प्रक्रिया कर्नेल स्पेस में विशेष रूप से पूरे सेकंड के लिए काम करती है। आइए देखें कि अंदर क्या हो रहा था।

इतना धीमा क्यों?

इस मामले में, हमने पूरे सिस्टम से नमूने लिए:

 perf record -a -g -- sleep 22 perf script > perf.results

सभी CPU से निशान हटाने के लिए perf के लिए The -a विकल्प की आवश्यकता है।

बढ़े हुए CPU लोड के क्षण को ट्रैक करने के लिए flamescope के साथ perf.results खोलें।

हीटमैप

हमसे पहले एक "हीट मैप" है, दोनों अक्ष (एक्स और वाई) जिनमें से समय का प्रतिनिधित्व करते हैं।

एक्स अक्ष पर, अंतरिक्ष सेकंड में विभाजित है, और वाई अक्ष पर, एक्स सेकंड के भीतर 20 मिलीसेकंड के खंडों में। समय नीचे से ऊपर और बाएं से दाएं चलता है। सबसे चमकीले वर्गों में नमूनों की सबसे बड़ी संख्या है। यही है, इस समय सीपीयू ने सबसे सक्रिय रूप से काम किया।

दरअसल, हम बीच में रेड स्पॉट में रुचि रखते हैं। इसे माउस से चुनें, क्लिक करें और देखें कि यह क्या छुपाता है:

सामान्य तौर पर, यह पहले से ही स्पष्ट है कि समस्या इसमें tcp_recvmsg और skb_copy_datagram_iovec धीमा संचालन है।

स्पष्टता के लिए, किसी अन्य होस्ट के नमूनों की तुलना करें, जिस पर आने वाले ट्रैफ़िक की समान मात्रा समस्याओं का कारण नहीं है:

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

हम मंच को पुनः आरंभ करते हैं। BIOS को लोड करते समय, हम एक टूटी हुई मेमोरी बार के बारे में एक संदेश देखते हैं। प्रतिस्थापन, मेजबान शुरू होता है और एक अतिभारित सीपीयू के साथ समस्या अब पुन: पेश नहीं की जाती है।

उपसंहार

सिस्टम प्रदर्शन के साथ पूर्ण

आम तौर पर, एक व्यस्त प्रणाली पर, चलने वाला perf प्रसंस्करण अनुरोधों में देरी का परिचय दे सकता है। इन देरी का आकार सर्वर पर लोड पर भी निर्भर करता है।

आइए इस देरी को खोजने की कोशिश करते हैं:

 ~# /root/fio/fio --clocksource=cpu --name=test --bs=4k --filename=/dev/nvme0n1p4 --direct=1 --ioengine=pvsync2 --hipri --rw=randread --filesize=4G --loops=1 test: (g=0): rw=randread, bs=(R) 4096B-4096B, (W) 4096B-4096B, (T) 4096B-4096B, ioengine=pvsync2, iodepth=1 fio-3.9-dirty Starting 1 process Jobs: 1 (f=1): [r(1)][100.0%][r=413MiB/s][r=106k IOPS][eta 00m:00s] test: (groupid=0, jobs=1): err= 0: pid=109786: Wed Dec 12 17:25:56 2018 read: IOPS=106k, BW=414MiB/s (434MB/s)(4096MiB/9903msec) clat (nsec): min=8161, max=84768, avg=9092.68, stdev=1866.73 lat (nsec): min=8195, max=92651, avg=9127.03, stdev=1867.13 … ~# perf record /root/fio/fio --clocksource=cpu --name=test --bs=4k --filename=/dev/nvme0n1p4 --direct=1 --ioengine=pvsync2 --hipri --rw=randread --filesize=4G --loops=1 test: (g=0): rw=randread, bs=(R) 4096B-4096B, (W) 4096B-4096B, (T) 4096B-4096B, ioengine=pvsync2, iodepth=1 fio-3.9-dirty Starting 1 process Jobs: 1 (f=1): [r(1)][100.0%][r=413MiB/s][r=106k IOPS][eta 00m:00s] test: (groupid=0, jobs=1): err= 0: pid=109839: Wed Dec 12 17:27:50 2018 read: IOPS=106k, BW=413MiB/s (433MB/s)(4096MiB/9916msec) clat (nsec): min=8259, max=55066, avg=9102.88, stdev=1903.37 lat (nsec): min=8293, max=55096, avg=9135.43, stdev=1904.01

अंतर बहुत ही ध्यान देने योग्य नहीं है, केवल ~ 8 नैनोसेकंड के बारे में।

आइए देखें कि यदि आप लोड बढ़ाते हैं तो क्या होता है:

 ~# /root/fio/fio --clocksource=cpu --name=test --numjobs=4 --bs=4k --filename=/dev/nvme0n1p4 --direct=1 --ioengine=pvsync2 --hipri --rw=randread --filesize=4G --loops=1 test: (g=0): rw=randread, bs=(R) 4096B-4096B, (W) 4096B-4096B, (T) 4096B-4096B, ioengine=pvsync2, iodepth=1 ... fio-3.9-dirty Starting 4 processes Jobs: 4 (f=4): [r(4)][100.0%][r=1608MiB/s][r=412k IOPS][eta 00m:00s] ~# perf record /root/fio/fio --clocksource=cpu --name=test --numjobs=4 --bs=4k --filename=/dev/nvme0n1p4 --direct=1 --ioengine=pvsync2 --hipri --rw=randread --filesize=4G --loops=1 test: (g=0): rw=randread, bs=(R) 4096B-4096B, (W) 4096B-4096B, (T) 4096B-4096B, ioengine=pvsync2, iodepth=1 ... fio-3.9-dirty Starting 4 processes Jobs: 4 (f=4): [r(4)][100.0%][r=1584MiB/s][r=405k IOPS][eta 00m:00s]

यहां अंतर पहले से ही ध्यान देने योग्य हो रहा है। यह कहा जा सकता है कि सिस्टम 1% से कम धीमा हो गया, लेकिन अनिवार्य रूप से एक भारी लोड सिस्टम पर लगभग 7Kiops खोने से समस्याएं हो सकती हैं।

यह स्पष्ट है कि यह उदाहरण सिंथेटिक है, फिर भी यह बहुत खुलासा करता है।

आइए एक और सिंथेटिक परीक्षण चलाने की कोशिश करें जो प्रमुख संख्याओं की गणना करता है - sysbench :

 ~# sysbench --max-time=10 --test=cpu run --num-threads=10 --cpu-max-prime=100000 ... Test execution summary: total time: 10.0140s total number of events: 3540 total time taken by event execution: 100.1248 per-request statistics: min: 28.26ms avg: 28.28ms max: 28.53ms approx. 95 percentile: 28.31ms Threads fairness: events (avg/stddev): 354.0000/0.00 execution time (avg/stddev): 10.0125/0.00 ~# perf record sysbench --max-time=10 --test=cpu run --num-threads=10 --cpu-max-prime=100000 … Test execution summary: total time: 10.0284s total number of events: 3498 total time taken by event execution: 100.2164 per-request statistics: min: 28.53ms avg: 28.65ms max: 28.89ms approx. 95 percentile: 28.67ms Threads fairness: events (avg/stddev): 349.8000/0.40 execution time (avg/stddev): 10.0216/0.01

यहां आप देख सकते हैं कि न्यूनतम प्रसंस्करण समय में 270 माइक्रोसेकंड की वृद्धि हुई है।

एक निष्कर्ष के बजाय

सिस्टम प्रदर्शन और डीबगिंग का विश्लेषण करने के लिए perf एक बहुत शक्तिशाली उपकरण है। हालांकि, किसी भी अन्य उपकरण की तरह, आपको अपने आप को नियंत्रण में रखने की आवश्यकता है और याद रखें कि निकट पर्यवेक्षण के तहत कोई भी लोड सिस्टम बदतर काम करता है।

संबंधित लिंक:

इत्र और लौ