Netflix Linux Perf Analysis 60s PDF

Preview

Summary

Application Performance Analysis...

Description

67

 More  NextBlog»

[email protected]  NewPost  SignOut

Monday,November30,2015

Links

LinuxPerformanceAnalysisin60,000Milliseconds

NetflixUS&CanadaBlog NetflixAmericaLatinaBlog

YoulogintoaLinuxserverwithaperformanceissue:whatdoyoucheckinthefirstminute? NetflixBrasilBlog

AtNetflixwehaveamassiveEC2Linuxcloud,andnumerousperformanceanalysistoolstomonitorand investigateitsperformance.TheseincludeAtlasforcloudwidemonitoring,andVectorforondemand instanceanalysis.Whilethosetoolshelpussolvemostissues,wesometimesneedtologintoaninstance andrunsomestandardLinuxperformancetools.

NetflixBeneluxBlog

Inthispost,theNetflixPerformanceEngineeringteamwillshowyouthefirst60secondsofanoptimized performanceinvestigationatthecommandline,usingstandardLinuxtoolsyoushouldhaveavailable.

NetflixNordicsBlog

NetflixFranceBlog

NetflixUK&IrelandBlog NetflixISPSpeedIndex

First60Seconds:Summary In60secondsyoucangetahighlevelideaofsystemresourceusageandrunningprocessesbyrunningthe followingtencommands.Lookforerrorsandsaturationmetrics,astheyarebotheasytointerpret,andthen resourceutilization.Saturationiswherearesourcehasmoreloadthanitcanhandle,andcanbeexposed eitherasthelengthofarequestqueue,ortimespentwaiting.

OpenpositionsatNetflix NetflixWebsite FacebookNetflixPage NetflixUIEngineering

uptime dmesg | tail vmstat 1 mpstat -P ALL 1 pidstat 1 iostat -xz 1 free -m sar -n DEV 1 sar -n TCP,ETCP 1 top

RSSFeed

AbouttheNetflixTechBlog

Someofthesecommandsrequirethesysstatpackageinstalled.Themetricsthesecommandsexposewill helpyoucompletesomeoftheUSEMethod:amethodologyforlocatingperformancebottlenecks.This involvescheckingutilization,saturation,anderrormetricsforallresources(CPUs,memory,disks,e.t.c.). Alsopayattentiontowhenyouhavecheckedandexoneratedaresource,asbyprocessofeliminationthis narrowsthetargetstostudy,anddirectsanyfollowoninvestigation. Thefollowingsectionssummarizethesecommands,withexamplesfromaproductionsystem.Formore informationaboutthesetools,seetheirmanpages.

ThisisaNetflixblogfocusedon technologyandtechnologyissues. We'llshareourperspectives, decisionsandchallengesregarding thesoftwarewebuildanduseto createtheNetflixservice.

BlogArchive ▼2015(43) ▼November(5) LinuxPerformance Analysisin60,000 Milliseconds

1.uptime $ uptime 23:51:26 up 21:31,

NetflixDACHBlog

1 user,

load average: 30.02, 26.43, 19.02

Thisisaquickwaytoviewtheloadaverages,whichindicatethenumberoftasks(processes)wantingto run.OnLinuxsystems,thesenumbersincludeprocesseswantingtorunonCPU,aswellasprocesses blockedinuninterruptibleI/O(usuallydiskI/O).Thisgivesahighlevelideaofresourceload(ordemand),but can’tbeproperlyunderstoodwithoutothertools.Worthaquicklookonly. Thethreenumbersareexponentiallydampedmovingsumaverageswitha1minute,5minute,and15 minuteconstant.Thethreenumbersgiveussomeideaofhowloadischangingovertime.Forexample,if you’vebeenaskedtocheckaproblemserver,andthe1minutevalueismuchlowerthanthe15minute value,thenyoumighthaveloggedintoolateandmissedtheissue.

CreatingYourOwn EC2SpotMarket Part2 SleepyPuppy ExtensionforBurp Suite GlobalContinuous Deliverywith Spinnaker NetflixHackDay Autumn2015 ►October(5) ►September(6)

Intheexampleabove,theloadaveragesshowarecentincrease,hitting30forthe1minutevalue,compared to19forthe15minutevalue.Thatthenumbersarethislargemeansalotofsomething:probablyCPU demand;vmstatormpstatwillconfirm,whicharecommands3and4inthissequence.

►August(6) ►July(3) ►June(2)

2.dmesg|tail

►May(2) ►April(3)

$ dmesg | tail [1880957.563150] [...] [1880957.563400] [1880957.563408] ss:0kB [2320864.954447] nters.

►March(3) perl invoked oom-killer: gfp_mask=0x280da, order=0, oom_score_adj=0

►February(5)

Out of memory: Kill process 18694 (perl) score 246 or sacrifice child Killed process 18694 (perl) total-vm:1972392kB, anon-rss:1953348kB, file-r

►January(3)

TCP: Possible SYN flooding on port 7001. Dropping request.

Check SNMP cou

►2014(37) ►2013(52) ►2012(37) ►2011(17)

Thisviewsthelast10systemmessages,ifthereareany.Lookforerrorsthatcancauseperformance issues.Theexampleaboveincludestheoomkiller,andTCPdroppingarequest.

►2010(8)

Don’tmissthisstep!dmesgisalwaysworthchecking.

Labels

3.vmstat1

acceleratedcompositing(2) $ vmstat 1 procs ---------memory---------- ---swap-- -----io---- -system-- ------cpu----r b swpd free buff cache si so bi bo in cs us sy id wa st 34 0 0 200889792 73708 591828 0 0 0 5 6 10 96 1 3 0 0 32 0 0 200889920 73708 591860 0 0 0 592 13284 4282 98 1 1 0 0 32 0 0 200890112 73708 591860 0 0 0 0 9501 2154 99 1 0 0 0 32 0 0 200889568 73712 591856 0 0 0 48 11900 2459 99 0 0 0 0 32 0 0 200890208 73712 591860 0 0 0 0 15898 4840 98 1 1 0 0 ^C

Shortforvirtualmemorystat,vmstat(8)isacommonlyavailabletool(firstcreatedforBSDdecadesago).It printsasummaryofkeyserverstatisticsoneachline. vmstatwasrunwithanargumentof1,toprintonesecondsummaries.Thefirstlineofoutput(inthisversion ofvmstat)hassomecolumnsthatshowtheaveragesinceboot,insteadoftheprevioussecond.Fornow, skipthefirstline,unlessyouwanttolearnandrememberwhichcolumniswhich. Columnstocheck:

adwords(1) Aegisthus(1) algorithms(2) aminator(1) analytics(4) Android(2) angular(1) api(16) appender(1) Archaius(2) architecturaldesign(1)

r:NumberofprocessesrunningonCPUandwaitingforaturn.Thisprovidesabettersignalthan loadaveragesfordeterminingCPUsaturation,asitdoesnotincludeI/O.Tointerpret:an“r”value greaterthantheCPUcountissaturation.

architecture(1)

free:Freememoryinkilobytes.Iftherearetoomanydigitstocount,youhaveenoughfree memory.The“freem”command,includedascommand7,betterexplainsthestateoffree memory.

Astyanax(3)

Asgard(1)

authentication(1) automation(2)

si,so:Swapinsandswapouts.Ifthesearenonzero,you’reoutofmemory.

autoscaling(3)

us,sy,id,wa,st:ThesearebreakdownsofCPUtime,onaverageacrossallCPUs.Theyare usertime,systemtime(kernel),idle,waitI/O,andstolentime(byotherguests,orwithXen,the guest'sownisolateddriverdomain).

availability(4) AWS(29)

TheCPUtimebreakdownswillconfirmiftheCPUsarebusy,byaddinguser+systemtime.Aconstant degreeofwaitI/Opointstoadiskbottleneck;thisiswheretheCPUsareidle,becausetasksareblocked waitingforpendingdiskI/O.YoucantreatwaitI/OasanotherformofCPUidle,onethatgivesaclueasto whytheyareidle.

benchmark(2) bigdata(10) billing(1)

SystemtimeisnecessaryforI/Oprocessing.Ahighsystemtimeaverage,over20%,canbeinterestingto explorefurther:perhapsthekernelisprocessingtheI/Oinefficiently.

Blitz4j(1)

Intheaboveexample,CPUtimeisalmostentirelyinuserlevel,pointingtoapplicationlevelusageinstead. TheCPUsarealsowellover90%utilizedonaverage.Thisisn’tnecessarilyaproblem;checkforthedegree ofsaturationusingthe“r”column.

Cable(1)

build(3)

caching(2) Cassandra(13)

4.mpstatPALL1 chaosengineering(1) $ mpstat -P ALL 1 Linux 3.13.0-49-generic (titanclusters-xxxxx)

07/14/2015

chaosmonkey(5)

_x86_64_ (32 CPU)

ci(1) 07:38:49 07:38:50 07:38:50 07:38:50 07:38:50 07:38:50 [...]

PM PM PM PM PM PM

CPU all 0 1 2 3

%usr 98.47 96.04 97.00 98.00 96.97

%nice 0.00 0.00 0.00 0.00 0.00

%sys %iowait 0.75 0.00 2.97 0.00 1.00 0.00 1.00 0.00 0.00 0.00

%irq 0.00 0.00 0.00 0.00 0.00

%soft 0.00 0.00 0.00 0.00 0.00

%steal 0.00 0.00 0.00 0.00 0.00

%guest 0.00 0.00 0.00 0.00 0.00

%gnice 0.00 0.00 0.00 0.00 0.00

%idle 0.78 0.99 2.00 1.00 3.03

classloaders(1) Clojure(1) cloud(23) cloudarchitecture(15)

ThiscommandprintsCPUtimebreakdownsperCPU,whichcanbeusedtocheckforanimbalance.A singlehotCPUcanbeevidenceofasinglethreadedapplication.

cloudprize(3) CO2(1)

5.pidstat1

collection(1) computervision(1)

$ pidstat 1 Linux 3.13.0-49-generic (titanclusters-xxxxx)

07/14/2015

_x86_64_

(32 CPU)

07:41:02 07:41:03 07:41:03 07:41:03 07:41:03 07:41:03 07:41:03

PM UID PM 0 PM 0 PM 0 PM 0 PM 0 PM 60004

PID %usr %system 9 0.00 0.94 4214 5.66 5.66 4354 0.94 0.94 6521 1596.23 1.89 6564 1571.70 7.55 60154 0.94 4.72

%guest %CPU 0.00 0.94 0.00 11.32 0.00 1.89 0.00 1598.11 0.00 1579.25 0.00 5.66

CPU 1 15 8 27 28 9

Command rcuos/0 mesos-slave java java java pidstat

07:41:03 07:41:04 07:41:04 07:41:04 07:41:04 07:41:04 ^C

PM UID PM 0 PM 0 PM 0 PM 108 PM 60004

PID %usr %system 4214 6.00 2.00 6521 1590.00 1.00 6564 1573.00 10.00 6718 1.00 0.00 60154 1.00 4.00

%guest %CPU 0.00 8.00 0.00 1591.00 0.00 1583.00 0.00 1.00 0.00 5.00

CPU 15 27 28 0 9

Command mesos-slave java java snmp-pass pidstat

concurrency(1) configuration(2) configurationmanagement(2) conformitymonkey(1) contentplatformengineering(2) continuousdelivery(4) coordination(2) costmanagement(1) crypto(1) Cryptography(2)

Pidstatisalittleliketop’sperprocesssummary,butprintsarollingsummaryinsteadofclearingthescreen. Thiscanbeusefulforwatchingpatternsovertime,andalsorecordingwhatyousaw(copynpaste)intoa recordofyourinvestigation.

CSS(2) CUDA(1) dart(1)

TheaboveexampleidentifiestwojavaprocessesasresponsibleforconsumingCPU.The%CPUcolumnis thetotalacrossallCPUs;1591%showsthatthatjavaprocessesisconsumingalmost16CPUs.

database(4) datamigration(1)

6.iostatxz1

datapipeline(4)

$ iostat -xz 1 Linux 3.13.0-49-generic (titanclusters-xxxxx) avg-cpu:

%user 73.96

Device: xvda xvdb xvdc dm-0 dm-1 dm-2 [...] ^C

rrqm/s 0.00 0.01 0.01 0.00 0.00 0.00

%nice %system %iowait 0.00 3.73 0.03

datascience(6) 07/14/2015

%steal 0.06

_x86_64_ (32 CPU)

DataStax(2)

%idle 22.21

datavisualization(1) deadlock(1)

wrqm/s 0.23 0.00 0.00 0.00 0.00 0.00

r/s 0.21 1.02 1.02 0.69 0.00 0.09

w/s 0.18 8.94 8.86 2.32 0.94 0.07

rkB/s 4.52 127.97 127.79 10.47 0.01 1.35

wkB/s avgrq-sz avgqu-sz 2.08 34.37 0.00 598.53 145.79 0.00 595.94 146.50 0.00 31.69 28.01 0.01 3.78 8.00 0.33 0.36 22.50 0.00

await 9.98 0.43 0.45 3.23 345.84 2.55

deeplearning(1) Denominator(2) dependencyinjection(1) device(3) deviceproliferation(1) devops(2)

Thisisagreattoolforunderstandingblockdevices(disks),boththeworkloadappliedandtheresulting performance.Lookfor: r/s,w/s,rkB/s,wkB/s:Thesearethedeliveredreads,writes,readKbytes,andwriteKbytesper secondtothedevice.Usetheseforworkloadcharacterization.Aperformanceproblemmay simplybeduetoanexcessiveloadapplied.

distributed(10) DNS(1) Docker(1) Dockerhub(1)

await:TheaveragetimefortheI/Oinmilliseconds.Thisisthetimethattheapplicationsuffers, asitincludesbothtimequeuedandtimebeingserviced.Largerthanexpectedaveragetimescan beanindicatorofdevicesaturation,ordeviceproblems.

DSL(1)

avgqusz:Theaveragenumberofrequestsissuedtothedevice.Valuesgreaterthan1canbe evidenceofsaturation(althoughdevicescantypicallyoperateonrequestsinparallel,especially virtualdeviceswhichfrontmultiplebackenddisks.)

DynECT(1)

Dyn(1)

efficiency(1) ElasticLoadBalancer(1)

%util:Deviceutilization.Thisisreallyabusypercent,showingthetimeeachsecondthatthe devicewasdoingwork.Valuesgreaterthan60%typicallyleadtopoorperformance(which shouldbeseeninawait),althoughitdependsonthedevice.Valuescloseto100%usually indicatesaturation. Ifthestoragedeviceisalogicaldiskdevicefrontingmanybackenddisks,then100%utilizationmayjust meanthatsomeI/Oisbeingprocessed100%ofthetime,however,thebackenddisksmaybefarfrom saturated,andmaybeabletohandlemuchmorework. BearinmindthatpoorperformingdiskI/Oisn’tnecessarilyanapplicationissue.Manytechniquesare

elasticsearch(1) ELB(1) EMR(2) encoding(2) energy(1) eucalyptus(1)

typicallyusedtoperformI/Oasynchronously,sothattheapplicationdoesn’tblockandsufferthelatency directly(e.g.,readaheadforreads,andbufferingforwrites).

eureka(2) evcache(1)

7.freem

failover(2) falcor(2)

$ free -m total Mem: 245998 -/+ buffers/cache: Swap: 0

used 24545 23944 0

free 221453 222053 0

shared 83

buffers 59

cached 541

faulttolerance(12) flamegraphs(1) Flow(1)

Therighttwocolumnsshow:

footprint(1)

buffers:Forthebuffercache,usedforblockdeviceI/O.

FRP(1)

cached:Forthepagecache,usedbyfilesystems.

functionalreactive(1)

Wejustwanttocheckthatthesearen’tnearzeroinsize,whichcanleadtohigherdiskI/O(confirmusing iostat),andworseperformance.Theaboveexamplelooksfine,withmanyMbytesineach.

garbage(1) garbagecollection(1)

The“/+buffers/cache”provideslessconfusingvaluesforusedandfreememory.Linuxusesfreememory forthecaches,butcanreclaimitquicklyifapplicationsneedit.Soinawaythecachedmemoryshouldbe includedinthefreememorycolumn,whichthislinedoes.There’sevenawebsite,linuxatemyram,aboutthis confusion.

gc(1) Genie(4) Governator(1)

ItcanbeadditionallyconfusingifZFSonLinuxisused,aswedoforsomeservices,asZFShasitsownfile systemcachethatisn’treflectedproperlybythefreemcolumns.Itcanappearthatthesystemislowon freememory,whenthatmemoryisinfactavailableforusefromtheZFScacheasneeded.

GPU(2) green(1) Groovy(1)

8.sarnDEV1

HackDay(3) $ sar -n DEV 1 Linux 3.13.0-49-generic (titanclusters-xxxxx)

07/14/2015

_x86_64_

Hadoop(12)

(32 CPU)

HBase(1) 12:16:48 12:16:49 12:16:49 12:16:49

AM AM AM AM

IFACE eth0 lo docker0

rxpck/s 18763.00 14.00 0.00

txpck/s 5032.00 14.00 0.00

rxkB/s 20686.42 1.36 0.00

txkB/s 478.30 1.36 0.00

rxcmp/s 0.00 0.00 0.00

txcmp/s 0.00 0.00 0.00

rxm

12:16:49 12:16:50 12:16:50 12:16:50 ^C

AM AM AM AM

IFACE eth0 lo docker0

rxpck/s 19763.00 20.00 0.00

txpck/s 5101.00 20.00 0.00

rxkB/s 21999.10 3.25 0.00

txkB/s 482.56 3.25 0.00

rxcmp/s 0.00 0.00 0.00

txcmp/s 0.00 0.00 0.00

rxm

highvolume(4) highvolumedistributedsystems(8) Hive(2) HTML5(7) https(1) Hystrix(5) IBM(1)

Usethistooltochecknetworkinterfacethroughput:rxkB/sandtxkB/s,asameasureofworkload,andalso tocheckifanylimithasbeenreached.Intheaboveexample,eth0receiveisreaching22Mbytes/s,whichis 176Mbits/sec(wellunder,say,a1Gbit/seclimit). Thisversionalsohas%ifutilfordeviceutilization(maxofbothdirectionsforfullduplex),whichissomething wealsouseBrendan’snicstattooltomeasure.Andlikewithnicstat,thisishardtogetright,andseemsto notbeworkinginthisexample(0.00).

ice(1) initialization(1) innovation(3) insights(1) interprocesscommunication(1)

9.sarnTCP,ETCP1

Ipv6(2)

$ sar -n TCP,ETCP 1 Linux 3.13.0-49-generic (titanclusters-xxxxx) 12:17:19 AM 12:17:20 AM

active/s passive/s 1.00 0.00

12:17:19 AM 12:17:20 AM

atmptf/s 0.00

12:17:20 AM 12:17:21 AM

active/s passive/s 1.00 0.00

12:17:20 AM 12:17:21 AM ^C

atmptf/s 0.00

iseg/s 10233.00

isolation(1) 07/14/2015

oseg/s 18846.00

_x86_64_

(32 CPU)

ISP(1) java(5) JavaScript(17)

estres/s retrans/s isegerr/s 0.00 0.00 0.00 iseg/s 8359.00

orsts/s 0.00

jenkins(1)

oseg/s 6039.00

estres/s retrans/s isegerr/s 0.00 0.00 0.00

ThisisasummarizedviewofsomekeyTCPmetrics.Theseinclude:

jclouds(1)

kafka(1) orsts/s 0.00

Karyon(2) lifecycle(1) linux(2) lipstick(2)

active/s:NumberoflocallyinitiatedTCPconnectionspersecond(e.g.,viaconnect()).

loadbalancing(3)

passive/s:NumberofremotelyinitiatedTCPconnectionspersecond(e.g.,viaaccept()).

localization(1)

retrans/s:NumberofTCPretransmitspersecond.

localizationplatformengineering(1)

Theactiveandpassivecountsareoftenusefulasaroughmeasureofserverload:numberofnewaccepted connections(passive),andnumberofdownstreamconnections(active).Itmighthelptothinkofactiveas outbound,andpassiveasinbound,butthisisn’tstrictlytrue(e.g.,consideralocalhosttolocalhost connection). Retransmitsareasignofanetworkorserverissue;itmaybeanunreliablenetwork(e.g.,thepublic Internet),oritmaybedueaserverbeingoverloadedanddroppingpackets.Theexampleaboveshowsjust onenewTCPconnectionpersecond.

locking(1) locks(1) log4j(1) logging(2) machinelearning(5) MapReduce(1)

10.top

meetup(3)

$ top top - 00:15:40 up 21:56, 1 user, load average: 31.09, 29.87, 29.92 Tasks: 871 total, 1 running, 868 sleeping, 0 stopped, 2 zombie %Cpu(s): 96.8 us, 0.4 sy, 0.0 ni, 2.7 id, 0.1 wa, 0.0 hi, 0.0 si, 0.0 st KiB Mem: 25190241+total, 24921688 used, 22698073+free, 60448 buffers KiB Swap: 0 total, 0 used, 0 free. 554208 cached Mem PID 20248 4213 66128 5235 4299 1 2 3 5 6 8

USER root root titancl+ root root root root root root root root

PR NI VIRT RES 20 0 0.227t 0.012t 20 0 2722544 64640 20 0 24344 2332 20 0 38.227g 547004 20 0 20.015g 2.682g 20 0 33620 2920 20 0 0 0 20 0 0 0 0 -20 0 0 20 0 0 0 20 0 0 0

SHR 18748 4423...