690 likes | 1.55k Views
Fly-by-Wire Instrument Mediated Performance Tuning Kirk Pepperdine kirk@kodewerk.com Fly-by-Wire A fly-by-wire system literally replaces physical control of the aircraft with an electrical interface. Wikipedia Computer mediated controls between the operator and the machine
E N D
Fly-by-Wire Instrument Mediated Performance Tuning Kirk Pepperdine kirk@kodewerk.com
Fly-by-Wire • A fly-by-wire system literally replaces physical control of the aircraft with an electrical interface. Wikipedia • Computer mediated controls between the operator and the machine • First attempted in test flight of F-8 (from NASA) • Pilot incapable of flying without assistance
Fly-by-Wire F-8 (from NASA galleries)
Reality vs. Senses • We learn to fly using sight • Licensed under Visual Flight Rules (VFR) • What happens when we can’t see? • Human senses are ill equipped for flight • Even when we can see we don’t always see things correctly • In order to see anything our brain fills in details
Reality vs. Senses • Conflict • All of our senses tell us one thing • You believe you are straight and level • Instrumentation tells us something else • Your attitude is sending you toward the ground
Fly-by-Wire My name is Bob and today I’ll be your pilot
Who I am • Kirk Pepperdine • Engaged around the world to solve Java performance problems • Co-author of http://www.javaperformancetuning.com • Associate Editor http://www.theserverside.com • Member of Sun Java Champions program
Our Typical Story • Customer JoGoSlo Ltd calls us in desperation • Users complain about poor performance • Customers consider abandoning the project • 1 Million € invested • Management applying pressure • Developers • Can’t reproduce the problem in development • Recoding parts of the system hasn’t produced results • Common comment, “maybe we should do this” • Working under stress
Effects of Stress • Learning and problem solving capabilities are impaired • During a stressful event, catecholamines suppress activity in areas at the front of the brain inhibiting the ability to handle complex social or intellectual tasks and behaviors • Why Zebras don’t get Ulcers (Robert M. Sapolsky) • In organizations you see “tribal” behaviours
Effects of Stress • Skills needed are impaired by the situation • Tend to rely on what you already know • Pilots may revert to VFR • Risk of crashing • Developers look at code • Risk missing the real problem
Senses public static boolean checkInteger(String testInteger) { try { //fails if not a number Integer theInteger = new Integer(testInteger); return (theInteger.toString() != "") && //not empty (theInteger.intValue() > 10) && ((theInteger.intValue() >= 2) && (theInteger.intValue() <= 100000)) && (theInteger.toString().charAt(0) == '3'); } catch (NumberFormatException err) { return false; } }
Senses public static void testDataset(String dataset) throws IOException { DataInputStream rdr = new DataInputStream(dataset); long starttime = System.currentTimeMillis(); int truecount = 0; String s; try { while ((s = rdr.readUTF()) != null) if (checkInteger(s)) truecount++; } catch (EOFException e) {} rdr.close(); System.out.println(truecount + " (count); time + (System.currentTimeMillis() - starttime)); }
Reality vs Senses • Why isn’t code enough? • Developers work in a static medium • Performance tuners work in a dynamic medium that includes • Users • Application • Hardware • Need to consider dynamic nature of systems • Users
Static View public static int[][] mul( int[][] a, int[][] b) { int rows = a.length; int columns = (a[ 0]).length; int[][] result = new int[rows][columns]; for ( int i = 0; i < rows; i++) for ( int j = 0; j < columns; j++) result[i][j] = a[i][j] * b[j][i]; return result; }
Dynamic View public static void main(String[] args) { int[][] a = { {1, 1}, {1, 1}, {1, 1}, {1, 1}, {1, 1}, {1, 1}, {1, 1}, {1, 1}}; int[][] b = { {1, 2, 3, 4, 5, 6, 7, 8}, {8, 7, 6, 5, 4, 3, 2, 1}}; long start = System.currentTimeMillis(); for ( int i = 0; i < 50000; i++) mul( b, a); System.out.println(System.currentTimeMillis() - start); start = System.currentTimeMillis(); for ( int i = 0; i < 50000; i++) mul( a, b); System.out.println(System.currentTimeMillis() - start); }
Dynamic Observation • Response time is king • Defines the user experience • 130ms vs 300ms • Same code • Same amount of data • Why the difference? • What are the elements of a system?
Elements of a System • Each layer contributes resources • Each layer defines whole classes of performance problems • Change a layer, change the problem • This include people
Hardware • Simply may not have enough • Buy more • May not be able to utilize more may • Utilization measured using • Unix : vmstat, iostat, mpstat, netstat, top • Windows : perfmon, taskmanager
Hardware - CPU • CPU consumption reaches 100% for extended periods of time • Real values are often 40-60% • Measure using • vmstat in Unix • Taskmanager in Windows
Hardware - CPU • Two different types of consumption • Application (user) • Operating System (system) • Need to be considered separately • Directs tuning efforts
Hardware – CPU • High system utilization • Tune OS • Application usage of system calls • Locks, frequent I/O, excessive context switching • High user utilization • Focus on the application (or JVM) • Not necessarily bad • Use response times as a guide • Consider peaks in utilization (capacity)
Hardware - Memory • System starved of memory • Will cause high system utilization • May appear to be an disk I/O bottleneck • Measured using • vmstat, swap, and scan rate columns • perfmon to report on counters • Best solution is buy more memory
Hardware – I/O • Symptoms • Low CPU utilization • Poor response times • Cannot boost CPU utilization • Can be measured with • iostat or netstat • Perfmon (network or disk counters) • Reported as absolute numbers • Need to know hardware supported rates
Hardware • If CPU, memory, disk and network I/O are all normal move to the JVM
JVM • Java memory is contained in Java heap • Managed by separate threads • Java process starved for memory will appear to be CPU bound • Large heap can cause lots of OS page swapping • Measure using –verbose:gc flag • Analyize output with GcViewer (Tagtram)
JVM Memory • Garbage collector (GC) manages Java heap memory • Look for GC efficiency • Defined as the portion of time spent managing memory over the run time duration • Values > 10% imply GC bottleneck • Tune generational spaces • Reduce memory utilization
Heaps of Heap 1.330: [GC 1232K->755K(1984K), 0.0016326 secs] 1.377: [GC 1264K->808K(1984K), 0.0017882 secs] 1.448: [GC 1319K->905K(1984K), 0.0020653 secs] 1.595: [GC 1417K->919K(1984K), 0.0019377 secs] 1.682: [GC 1431K->1027K(1984K), 0.0029697 secs] 2.457: [GC 1538K->1104K(1984K), 0.0033163 secs] 2.583: [GC 1616K->1248K(1984K), 0.0034569 secs] 2.745: [GC 1759K->1355K(1984K), 0.0020179 secs] 2.861: [GC 1866K->1462K(1984K), 0.0021721 secs] 2.964: [GC 1963K->1488K(2112K), 0.0019511 secs] 2.967: [Full GC 1488K->1190K(2112K), 0.0472200 secs]
Heaps of Heap 1.330: [GC 1232K->755K(1984K), 0.0016326 secs] 1.377: [GC 1264K->808K(1984K), 0.0017882 secs] 1.448: [GC 1319K->905K(1984K), 0.0020653 secs] 1.595: [Full GC 1488K->1190K(2112K), 0.0472200 secs] • Runtime = 1595 – 1330 = 265 • GC Time = 1.6326 + 1.7882 + 2.0653 + 47.22 = 52.7061 • GC efficiency = 52.7061 / 265 = 19.8%
JVM Threads • Too many threads • High system utilizations • High cpu utilization with slow progression • Threads also stress memory • Too few threads and processes will starve for CPU • Measuring using ^c in the console window • Dumps state of all threads
Webserver Thread Dump Full thread dump Java HotSpot(TM) Server VM (1.4.2_08-b03 mixed mode): "RMI ConnectionExpiration-[192.168.0.15:34113]" daemon prio=1 tid=0x0892f658 nid=0x2d7a waiting on condition [5b86f000..5b86f494] at java.lang.Thread.sleep(Native Method) at sun.rmi.transport.tcp.TCPChannel$Reaper.run(TCPChannel.java:447) at java.lang.Thread.run(Thread.java:534) "RMI TCP Connection(902)-192.168.0.15" daemon prio=1 tid=0x41e112b8 nid=0x2d7a runnable [5ccff000..5ccff414] at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.read(SocketInputStream.java:129) at java.io.BufferedInputStream.fill(BufferedInputStream.java:183) at java.io.BufferedInputStream.read(BufferedInputStream.java:201) - locked <0x49978800> (a java.io.BufferedInputStream) at java.io.FilterInputStream.read(FilterInputStream.java:66) at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java) at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport) at java.lang.Thread.run(Thread.java:534)
Webserver Thread Dump "PingThread-8692809" daemon prio=1 tid=0x081a3058 nid=0x2d7a waiting on condition [5bda9000..5bda9294] at java.lang.Thread.sleep(Native Method) at org.exolab.jms.client.rmi.RmiJmsConnectionStub$PingThread.run(RmiJmsConnectionStub.java:249) "EventManagerThread" daemon prio=1 tid=0x083101f8 nid=0x2d7a in Object.wait() [5caa9000..5caa9514] at java.lang.Object.wait(Native Method) - waiting on <0x47aa2800> (a java.lang.Object) at java.lang.Object.wait(Object.java:429) at org.exolab.jms.events.BasicEventManager.run(BasicEventManager.java) - locked <0x47aa2800> (a java.lang.Object) at java.lang.Thread.run(Thread.java:534) "PingThread-18183604" daemon prio=1 tid=0x08136dc8 nid=0x2d7a waiting on condition [5cc7f000..5cc7f494] at java.lang.Thread.sleep(Native Method) at org.exolab.jms.client.rmi.RmiJmsConnectionStub$PingThread.run( RmiJmsConnectionStub.java:249)
Webserver Thread Dump "RMI RenewClean-[192.168.0.15:34113]" daemon prio=1 tid=0x081a2c68 nid=0x2d7a in Object.wait() [5ba10000..5ba10594] at java.lang.Object.wait(Native Method) - waiting on <0x4858a940> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:111) - locked <0x4858a940> (a java.lang.ref.ReferenceQueue$Lock) at sun.rmi.transport.DGCClient$EndpointEntry$RenewCleanThread.run( DGCClient.java:500) at java.lang.Thread.run(Thread.java:534) "BoundedThreadPool0-33" prio=1 tid=0x41ec8710 nid=0x2d7a in Object.wait() [5ca29000..5ca29594] at java.lang.Object.wait(Native Method) - waiting on <0x47a5> (a org.mortbay.thread.BoundedThreadPool$PoolThread) at org.mortbay.thread.BoundedThreadPool$PoolThread.run(BoundedThreadPool) - locked <0x47a520b8> (a org.mortbay.thread.BoundedThreadPool$PoolThread)
Webserver Thread Dump "BoundedThreadPool0-32" prio=1 tid=0x5a159ed0 nid=0x2d7a runnable [5c9a9000..5c9a9614] at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.read(SocketInputStream.java:129) at org.mortbay.io.bio.StreamEndPoint.fill(StreamEndPoint.java:99) at org.mortbay.jetty.bio.SocketConnector$Connection.fill(SocketConnector) at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:257) at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:192) at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:293) at org.mortbay.jetty.bio.SocketConnector$Connection.run(SocketConnector) at org.mortbay.thread.BoundedThreadPool$PoolThread.run(BoundedThreadPool) - locked <0x47a521f8> (a org.mortbay.thread.BoundedThreadPool$PoolThread)
Webserver Thread Dump "BoundedThreadPool0-31" prio=1 tid=0x5ad60d78 nid=0x2d7a runnable [5c929000..5c929694] at org.mortbay.jetty.HttpGenerator.prepareBuffers(HttpGenerator.java:878) at org.mortbay.jetty.HttpGenerator.flushBuffers(HttpGenerator.java:681) at org.mortbay.jetty.HttpGenerator.complete(HttpGenerator.java:671) at org.mortbay.jetty.HttpConnection.doHandler(HttpConnection.java:388) at org.mortbay.jetty.HttpConnection.access$1500(HttpConnection.java:38) at org.mortbay.jetty.HttpConnection$RequestHandler.headerComplete( HttpConnection.java:598) at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:487) at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:196) at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:293) at org.mortbay.jetty.bio.SocketConnector$Connection.run(SocketConnector) at org.mortbay.thread.BoundedThreadPool$PoolThread.run(BoundedThreadPool) - locked <0x47a52158> (a org.mortbay.thread.BoundedThreadPool$PoolThread)
Webserver Thread Dump "BoundedThreadPool0-30" prio=1 tid=0x41e2f878 nid=0x2d7a in Object.wait() [5c8a9000..5c8a9714] at java.lang.Object.wait(Native Method) - waiting on <0x47a5> (a org.mortbay.thread.BoundedThreadPool$PoolThread) at org.mortbay.thread.BoundedThreadPool$PoolThread.run(BoundedThreadPool) - locked <0x47a52298> (a org.mortbay.thread.BoundedThreadPool$PoolThread) "BoundedThreadPool0-29" prio=1 tid=0x5a4c5650 nid=0x2d7a in Object.wait() [5c828000..5c828794] at java.lang.Object.wait(Native Method) - waiting on <0x47a5> (a org.mortbay.thread.BoundedThreadPool$PoolThread) at org.mortbay.thread.BoundedThreadPool$PoolThread.run(BoundedThreadPool) - locked <0x47a52108> (a org.mortbay.thread.BoundedThreadPool$PoolThread) "BoundedThreadPool0-28" prio=1 tid=0x5a4c53f8 nid=0x2d7a runnable [5c7a8000..5c7a8814] at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.read(SocketInputStream.java:129) at org.mortbay.io.bio.StreamEndPoint.fill(StreamEndPoint.java:99) at org.mortbay.jetty.bio.SocketConnector$Connection.fill(SocketConnector) at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:257) at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:192) at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:293) at org.mortbay.jetty.bio.SocketConnector$Connection.run(SocketConnector)
Webserver Thread Dump "BoundedThreadPool0-27" prio=1 tid=0x41e6a640 nid=0x2d7a in Object.wait() [5c728000..5c728894] at java.lang.Object.wait(Native Method) - waiting on <0x47a5> (a org.mortbay.thread.BoundedThreadPool$PoolThread) at org.mortbay.thread.BoundedThreadPool$PoolThread.run(BoundedThreadPool) - locked <0x47a52338> (a org.mortbay.thread.BoundedThreadPool$PoolThread) "BoundedThreadPool0-26" prio=1 tid=0x41e693f8 nid=0x2d7a in Object.wait() [5c6a8000..5c6a8914] at java.lang.Object.wait(Native Method) - waiting on <0x47a5> (a org.mortbay.thread.BoundedThreadPool$PoolThread) at org.mortbay.thread.BoundedThreadPool$PoolThread.run(BoundedThreadPool) - locked <0x47a52248> (a org.mortbay.thread.BoundedThreadPool$PoolThread) "BoundedThreadPool0-25" prio=1 tid=0x086b1c50 nid=0x2d7a in Object.wait() [5c628000..5c628994] at java.lang.Object.wait(Native Method) - waiting on <0x47a4> (a org.mortbay.thread.BoundedThreadPool$PoolThread) at org.mortbay.thread.BoundedThreadPool$PoolThread.run(BoundedThreadPool) - locked <0x47a4e180> (a org.mortbay.thread.BoundedThreadPool$PoolThread)
Webserver Thread Dump • According to client, system was idle • Did not accept any more connection requests • Let’s go back a few slides… • Why was HttpGenerator.prepareBuffers() being called?
Webserver Thread Dump "BoundedThreadPool0-31" prio=1 tid=0x5ad60d78 nid=0x2d7a runnable [5c929000..5c929694] at org.mortbay.jetty.HttpGenerator.prepareBuffers(HttpGenerator.java:878) at org.mortbay.jetty.HttpGenerator.flushBuffers(HttpGenerator.java:681) at org.mortbay.jetty.HttpGenerator.complete(HttpGenerator.java:671) at org.mortbay.jetty.HttpConnection.doHandler(HttpConnection.java:388) at org.mortbay.jetty.HttpConnection.access$1500(HttpConnection.java:38) at org.mortbay.jetty.HttpConnection$RequestHandler.headerComplete( HttpConnection.java:598) at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:487) at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:196) at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:293) at org.mortbay.jetty.bio.SocketConnector$Connection.run(SocketConnector) at org.mortbay.thread.BoundedThreadPool$PoolThread.run(BoundedThreadPool) - locked <0x47a52158> (a org.mortbay.thread.BoundedThreadPool$PoolThread)
JVM Threads • Use thread pooling to control over-utilization • Acts to calm traffic • Smoothen traffic reduces thrashing • Reduced thrashing increases throughput • Should reduce response times
Application • Applications • Interact with external systems • Add locks to protect software resources • The only things to consider are lock contention and interactions with external systems
Application • Measure using ^c in the console window • Lock contention • Threads waiting on monitors • Waits for external systems • Almost all communications with external systems occur via sockets • Threads waiting on socket read/write
Application • Most problematic external system • Relational databases • Monitor with intercepting technology • P6spy acts like a jdbc driver • Logs interactions • Logs can be viewed with Ironeye (source forge)