操作系統(tǒng)_清華大學(xué)-參考analysis

1、Operating System LaboratoryYong XIANGDept. of Computer Sci. & Tech., Tsinghua Univ. Lecture 3: Kernel Dynamic AnalysisOutlineOutlineBackgroundgprofDTraceSystemTapftraceS2EDynamic analysisDynamic analysisExecute program (over some inputs)The compiler provides the semanticsObserve executionsRequir

2、es instrumentation infrastructureMust choose what to measure, and what test runsResearch challenge: What to measure?Research challenge: What to measure?Coverage or frequencyStatements, branches, paths, procedure calls, types, method dispatchValues computedParameters, array indicesRun time, memory us

3、ageLike abstraction, determines what is reportedResearch challenge: Choose good testsResearch challenge: Choose good testsThe test suite determines the expense (in time and space)The test suite determines the accuracy (what executions are never seen)Less accurate results are poor for applications th

4、at require correctnessMany domains do not require correctness!*What information is being collected also mattersOutlineOutlineBackgroundgprofDTraceSystemTapftraceS2EGNU gprof time profiler GNU gprof time profiler Detail time statistics for each subroutine.Create relative graph for all subroutines.Ana

5、lysis the program bottleneck.Increase about 30% extra time cost.Steps for Profiling a program with gprofSteps for Profiling a program with gprofCompile and link a program with profiling enabledProgram is compiled with -pg optionEvery function to call mcount as one of its first operationsmcount routi

6、ne records in an in-memory call graph tableprofil() system call examines the users program counter (PC) every virtual 10 millisecondsExecute a program to generate its profile dataGenerating the file gmon.outRun gprof to analyze the profile datagprofs symbol table, an array of Sym structures, is buil

7、tGNU gprof time profiler GNU gprof time profiler pile the original source code -pg: This option affects both compiling and linking. Add additional commands into source code when compiling code in order to trace all subroutines. Add essential initial settings and statistical processes when linking th

8、e objects.gcc pg SourceCode o ExecutableFileykhongvangogh home$ gcc pg test2.c o test2GNU gprof time profiler GNU gprof time profiler Convert produced profile data into text file - ListOfOptions can be omitted. - ExecuteFile can be omitted when the file name is a.out. - StatFiles can be omitted when

9、 the file name is gmon.out.gprof ListOfOptions ExecuteFile StatFiles OutputFile ykhongvangogh home$ gprof b test2 gmon.out output.txtGNU gprof time profiler GNU gprof time profiler Example Program subroutine relative graphGNU gprof time profiler GNU gprof time profiler Example Program ykhongvangogh

10、home$ gcc pg test.c o testykhongvangogh home$ ./testykhongvangogh home$ gprof b test gmon.out outputykhongvangogh home$ more outputGNU gprof time profiler GNU gprof time profiler Example Program Each sample counts as 0.01 seconds. % cumulative self self total time seconds seconds calls s/call s/call

11、 name 71.90 30.17 30.17 1 30.17 30.17 C3 19.42 38.32 8.15 2 4.07 4.07 B2 7.99 41.67 3.35 1 3.35 3.35 C2 0.00 41.67 0.00 1 0.00 37.60 A 0.00 41.67 0.00 1 0.00 33.52 B1 0.00 41.67 0.00 1 0.00 0.00 C1 0.00 41.67 0.00 1 0.00 4.07 DGNU gprof time profiler GNU gprof time profiler Example Program Call grap

12、hindex %time self children called name 1 100.0 0.00 41.67 main1 0.00 37.60 1/1 A2 0.00 4.07 1/1 D6- 0.00 37.60 1/1 main12 90.2 0.00 37.60 1 A2 0.00 33.52 1/1 B13 4.07 0.00 1/2 B25-OutlineOutlineBackgroundgprofDTraceSystemTapftraceS2EOverview of DTraceOverview of DTraceDTrace a dynamic tracing enviro

13、nment for SolarisCan be used to troubleshoot performance and logic problems in user applicationsFeatures of tracingUses dynamic binary instrumentationInserts instrumentation code in running processesHas specialized C-like language, DTerminologyProbes: points of instrumentationProviders: make probes

14、availableSpecific to Solaris (requires extensive OS kernel modification)DTrace: HistoryDTrace: History1996: conceived of by Bryan Cantrill while an undergrad at Brown2001: Started work on Dtrace wth Michael W. Shapiro2002: Early prototype, Adam H. Leventhal joined development2004: Appears in Solaris

15、2005: Sun releases DTrace source code, initial java support (dvm)2006: Ported to FreeBSD by John Birrell2007: To be released in MacOSX 10.5 “Leopard” and basis of XrayDTrace UsageDTrace UsageUsers write D programs that collect information at runtimeUsers invoke dtrace to insert instrumentation code

16、in kernel and user processesSecurity mechanism ensures code can be inserted only by authorized usersWhen events occur at runtime, users D code is executed by the DTrace providers, which causesInformation to be recordedData to be printedWhatever else users defines in their D programs!Many, many provi

17、ders exist for getting lots of different data from running programsDtrace featuresDtrace featuresProvides (30k) instrumentation pointsin the kernelin the C runtime library (libc.so)in the Java VM (libjvm.so)in Java itself (starting with Java 1.6)Safe (probes not allowed to crash system)Extensible (u

18、sers can implement their own instrumentation points)Predicates avoid retaining (copying, and storing) unneeded dataProvides scalable aggregation (sum, min, avg, quantize, count, etc.)High level awk-like language, called DDTrace ArchitectureDTrace ArchitectureD LanguageD LanguageSimplified C-like lan

19、guageUses C formatting conventionsNo conditionals or functions/methods/classesThe D language provides convenient features forGathering and statistical informationAggregating dataDisplaying function arguments or timing information (printf-like syntax)Speculative tracingStructure of a D programProbe d

20、escription that tells which provider to usePredicate that says when this probe should be executedAction statements that make up the body of the probeExample DTrace ProvidersExample DTrace Providerssyscall: makes a probe available at the entry to and return from every system callvminfo: makes a probe

21、 available on VM activity (page out, page faults, etc)profile: makes a probe available that can run every X millisecondsfpuinfo: makes a probe available when hardware floating point operations are emulated in softwareUsers can also create their own providers by using the DTrace APIEx: provide probes

22、 before/after a request is serviced in a web server or database serverExample one-linersExample one-liners System call count, by process dtrace -n syscall:entry num ame = count(); Files opened by process dtrace -n syscall:open*:entry printf(%s %s ame,copyinstr(arg0); Number of bytes read, by process

23、 dtrace -n sysinfo:readch bytes ame = sum(arg0); Write size distribution, by process dtrace -n sysinfo:writech dist ame = quantize(arg0); Sample java stack at 1001 Hertz (aka profile) dtrace -n profile-1001 /pid = $target/ numjstack() = count(); -p PID Example Toy D ProgramExample Toy D ProgramD cod

24、e/* Count off and report the number of seconds elapsed*/dtrace:BEGIN i = 0;profile:tick-1sec i = i + 1; trace(i);dtrace:END trace(i);nOutput# dtrace -s counter.ddtrace: script counter.d matched 3 probesCPU ID FUNCTION:NAME0 25499 :tick-1sec 10 25499 :tick-1sec 20 25499 :tick-1sec 30 25499 :tick-1sec

25、 40 25499 :tick-1sec 50 25499 :tick-1sec 6C0 2 :END 6#More Realistic ProgramMore Realistic ProgramD code to time read() and write() syscallsOutputsyscall:read:entry,syscall:write:entry/pid = $1/ tsprobefunc = timestamp;syscall:read:return,syscall:write:return/pid = $1 & tsprobefunc != 0/ printf(

26、%d nsecs, timestamp - tsprobefunc);# dtrace -s rwtime.d pgrep -n kshdtrace: script rwtime.d matched 4 probesCPU ID FUNCTION:NAME0 33 read:return 22644 nsecs0 33 read:return 3382 nsecs0 35 write:return 25952 nsecs0 33 read:return 916875239 nsecs0 35 write:return 27320 nsecs0 33 read:return 9022 nsecs

27、0 33 read:return 3776 nsecs0 35 write:return 17164 nsecs.DTrace CommentsDTrace CommentsGood pointsDoes not require application modification, can trace any PID on the systemCan use on production Solaris systemsCan add and remove probes without having to restart applicationsAuthors claim low overhead

28、when a handful of probes are enabledD code provides a bit of flexibility when tracking down problemsUses simple ASCII output (good for sed/awk/grep/perl support)Bad pointsUsers must learn new D languageTied very closely to Solaris kernelOnly low-level (OS-level) information providedUsers have to wri

29、te a lot of D code for operations that are much easier to get in other toolsE.g., using prof/gprof vs. dtrace aloneCant easily track time spent by user codePoor source code correlation Best case: function name and byte offset from stack dumpsOutlineOutlineBackgroundgprofDTraceSystemTapftraceS2ESyste

30、mTapSystemTapCan examine or modify any parameters and local variables visible at the probe pointStatistics gathering capabilities built inA number of safety features make it far harder to crash a running kernelAutomatically communicates with a user-level processPrevious example can be expressed far

31、easier:global countglobal countprobe kernel.function(generic_make_request) count+; probe kernel.function(generic_make_request) count+; probe begin log(starting probe) probe begin log(starting probe) probe end printf(generic_make_request() called %d times.,count); probe end printf(generic_make_reques

32、t() called %d times.,count); SystemTap processSystemTap processSystemtap processing stepsSystemtap processing stepsHow it worksHow it works1.SystemTap parses your code and identifies probe points and identifiers using the kernel debug info2.The script is translated into C code3.The C code is compile

33、d into a KProbe module4.A root-privileged deamon called “stpd” is started5.The compiled kernel module is inserted6.The module exports output via the “relayfs” virtual file system to stpd7.The stpd service delivers this data to the user process to outputWhere to probeWhere to probeSystemtap supports

34、a number of built-in events.What to do with it?What to do with it?Use SystemTap-derived data to make real-time decisions about CPU scalingTwo approachs:StatisticalGiven a set of kernel metrics x1.xn, find a function f(x1.xn) that yields the ideal CPU frequencyAlgorithmicGiven a performance metric p(

35、x1.xn), adjust the CPU frequency tentatively while observing feedback from p.CPU Scaling Agent(User process)SystemTap front-end(User process)SystemTap probe(Kernel module)CPUFreq.OutlineOutlineBackgroundgprofDTraceSystemTapftraceS2EWhat is Ftrace?What is Ftrace?Provides a generic framework for traci

36、ngInfrastructure for defining tracepointsAbility to register different kinds of tracersSpecialized data structure (ring buffer) for trace data storageFtrace ComponentsFtrace Componentsmcount Routinemcount Routinemcount is called by every kernel functionExcept inlines and a few special functionsMust

37、be a low-overhead routine patible with some compiler optimizationsE.g. cannot omit frame-pointers on ARMCompiler disables some optimizations automaticallyAnalysis of assembly indicates that mcount callers have well-defined framesDiagram of TrampolineDiagram of TrampolineCallerFunctionFunc exitTracer

38、mcountFunc entryTracerThead_infostruct ret_stackStackcaller 1caller 2ret addrCode to Call mcountCode to Call mcount00000570 :570: e1a0c00d mov ip, sp574: e92dd800 stmdb sp!, fp, ip, lr, pc578: e24cb004 sub fp, ip, #4 ; 0 x457c: e3a00001 mov r0, #1 ; 0 x1580: ebffffa0 bl 408 584: e3a00000 mov r0, #0

39、; 0 x0588: e89da800 ldmia sp, fp, sp, pc00000570 :570: e1a0c00d mov ip, sp574: e92dd800 stmdb sp!, fp, ip, lr, pc578: e24cb004 sub fp, ip, #4 ; 0 x457c: e1a0c00e mov ip, lr580: ebfffffe bl 0 584: 00000028 andeq r0, r0, r8, lsr #32588: e3a00001 mov r0, #1 ; 0 x158c: ebffff9d bl 408 590: e3a00000 mov

40、r0, #0 ; 0 x0594: e89da800 ldmia sp, fp, sp, pcRef: Function tracer的實現(xiàn)Trace setup at run-timeTrace setup at run-timePseudo-files in debugfse.g. mount debugfs t debugfs /debugSelect a tracere.g. echo function_duration current_tracerSet tracing parameterse.g. echo 100 tracing_threshholdecho duration-p

41、roc trace_optionsTrace Data CaptureTrace Data CaptureRing BufferSpecialized structure for collecting trace dataManages buffer as list of pagesLatest version is lockless for writingAbility to atomically reserve space for an eventAutomatic timestamp managementPer-cpu buffersAvoids requiring cross-CPU

42、synchronizationAlso avoids cache collisionsVery important for performanceFiltering by DurationFiltering by DurationCreated new function_duration tracerMethod:Dont save function entries to trace log at allOnly save call time on function return stackAt function exit, compare duration to threshholdOmit

43、 exit entry events for short duration functionsResults in simpler, and faster codeOnly issue is that log is displayed in order of function exit (not function entry)Can be solved with a simple sort on trace outputTrace OutputTrace OutputOutput is human readable textNo special tools required to collec

44、t trace dataExamples:cat traceReturns EOF at end of trace datacat trace_pipe | grep foo log.txtBlocks at end of trace dataQuick enable/disableecho 0 tracing_enabledExample of UseExample of Use$ mount debugfs -t debugfs /debug$ cd /debug/tracing$ cat available_tracersfunction_graph function_duration

45、function sched_switch nop$ echo 0 tracing_enabled$ echo 100 tracing_thresh$ echo function_duration current_tracer$ echo 1 tracing_enabled ; do ls /bin | sed s/a/z/g ; done ; echo 0 tracing_enabled$ echo duration-proc trace_options$ cat trace /tmp/trace.txt$ cat /tmp/trace.txt | sort k3 /tmp/trace.tx

46、t.sortedFunction Duration Results (sorted)Function Duration Results (sorted)# tracer: function_duration# CPU TASK/PID CALLTIME DURATION FUNCTION CALLS# | | | | | | | | | | 0) sed-562 | 502.854252393 | ! 436.833 us | bprm_mm_init 0) sed-562 | 502.854254893 | ! 321.500 us | mm_alloc 0) sed-562 | 502.8

47、54270893 | ! 296.500 us | mm_init 0) sed-562 | 502.854279393 | ! 266.166 us | get_pgd_slow 0) sed-562 | 502.854744059 | ! 229.500 us | prepare_binprm 0) sed-562 | 502.854765393 | ! 198.666 us | kernel_read 0) sed-562 | 502.854769226 | ! 183.333 us | vfs_read 0) sed-562 | 502.854780393 | ! 142.000 us

48、 | do_sync_read 0) sed-562 | 502.854785559 | ! 120.667 us | nfs_file_read 0) sed-562 | 502.854982393 | ! 538.000 us | copy_strings_kernel 0) sed-562 | 502.854985726 | ! 521.667 us | copy_strings 0) sed-562 | 502.854993893 | ! 470.000 us | get_arg_page 0) sed-562 | 502.854997226 | ! 455.500 us | get_

49、user_pages 0) sed-562 | 502.855000059 | ! 421.667 us | _get_user_pages 0) sed-562 | 502.855031393 | ! 285.666 us | handle_mm_fault 0) sed-562 | 502.855037726 | ! 101.833 us | _pte_allocPost-trace analysisPost-trace analysisfdd tool is provided to analyze dataWhat fdd shows:function counts, total tim

50、e, average durationsub-routine with the longest duration, how many times it was calledLocal time = total time minus sub-routine total timeIs approximately the cost of the local execution of a functionNotes:Total time may be wrong if process is scheduled out or if a filter was activeMay need an optio

51、n to subtract time that function was scheduled outYou can filter, sort, select output columns,etc.fdd Outputfdd Output$ fdd /tmp/trace.txt n 15Function Count Time Average Local - - - - -schedule 59 1497735270 25385343 1476642939sys_write 56 1373722663 24530761 2892665vfs_write 56 1367969833 24428032

52、 3473173tty_write 54 1342476332 24860672 1212301170do_path_lookup 95 1076524931 11331841 34682198_link_path_walk 99 1051351737 10619714 6702507rpc_call_sync 87 1033211085 11875989 1700178path_walk 94 1019263902 10843233 3425163rpc_run_task 87 960080412 11035407 2292360rpc_execute 87 936049887 107591

53、94 2316635_rpc_execute 87 932779083 10721598 11383353do_lookup 191 875826405 4585478 9510659call_transmit 100 785408085 7854080 5871339_nfs_revalidate_inode 38 696216223 18321479 1652173nfs_proc_getattr 38 690552053 18172422 1234634Performance issuesPerformance issuesOverhead of tracing can be bigAverage function duration = 3.22 sOverhead = 11.4 microseconds per functionUse a CPU-bound test to measure overhead“find /sys /dev/null”With an I/O-bound test (or