Messages in this thread | | | From | "Mike Spreitzer" <> | Date | Wed, 30 Jan 2002 16:32:08 -0500 | Subject | Reported CPU utilization of network server doing constant work - varies periodically |
| |
I am not a kernel hacker, but I think I have a kernel bug to report. I have a hard time believing something so basic can be broken, but I have ruled out every other explanation I can think of.
[1.] One line summary of the problem:
The CPU utilization reported through /proc/stat and the times() syscall varies significantly (e.g., factors over 2) even when I think the actual CPU consumption is essentially constant (e.g., varying by less than 10%).
[2.] Full description of the problem/report:
I have this problem with network services but not programs with narrower footprints (e.g., a simple loop). I noticed this problem when working with a more complex network service, but I have produced a very simple network service that illustrates the problem (sources are attached to this message). The simple server is a non-threaded C program. It listens on a TCP socket, accepts one connection at a time, and for that connection copies the input to the output, as long as there is input, through fixed buffers (no explicit malloc nor free in the loop). The multithreaded client connects to the server and then one thread goes into a simple loop that alternately sleeps and writes a fixed buffer, while another thread reads and verifies the echoes. I have some instrumentation built into the server program, and also use `procmeter3`, `ps`, and `top` to observe CPU and network throughput from both client and server machines. I see essentially constant throughput, in bytes/second averaged over each reporting period, as observed by `procmeter3` on both client and server, and also as reported by the instrumentation in my server program. I also wrote an instrumented user-level idle loop, and when I run it, `nice`d, in parallel with my simple server, it also reports counting at essentially (+- 1%) a constant rate, as averaged over each reporting period. But the reported CPU utilization of the simple network server varies over the same reporting periods. And when I run the `nice`d user-level idle loop in parallel, its reported CPU utilization also varies (so that the sum of the two is essentially 100%). The CPU utilization numbers get from the kernel to my eyes in the following ways. For one, I run procmeter3 (which get its CPU utilization information from /proc/stat) on the server machine, and ask it to show me "Stat-CPU" / "CPU" in graphical form (a snapshot is attached to this message). For another, my simple server reads the CPU line of /proc/stat every reporting period, and reports whole-machine CPU utilization based on that. Finally, my simple server also calls times() each loop iteration, and reports its per-process CPU utilization based on that, aggregated over each reporting period.
The CPU utilization can vary quite a lot. In one case, it varied from under 0.1% to about 50%, with a one-minute reporting period. That is, aggregated over one particular minute, less than one thousandth of the machine's CPU goes to my simple server, while it's half the CPU over the course of a different minute.
The variation usually has a fairly clearly-defined periodic shape. I have seen periods as low as 63 seconds and as high as 114 minutes; colleagues report seeing periods up to about 150 minutes. I have not been able to determine what the period correlates with. It holds fairly constant for a given <client machine, client program & parameters, server machine, server program & parameters> tuple. I can vary some of the parameters without significantly changing the period. For fixed programs and parameters, the period can vary greatly for different choices of <client machine, server machine>.
I have looked for this problem on uniprocessor Pentium machines assembled by IBM, and seen it on every such machine at which I looked. They have been Intellistation M-Pro and PC 300 machines. When the simple server was run on an Intellistation M-Pro, the CPU variation's period was in the 1 to 3 minute range, and a one minute reporting period was too short to make the pattern clear. I saw the pattern with a reporting period of 10 seconds, and saw it more clearly with a reporting period of 5 seconds. When the simple server was run on a PC 300 machine, the CPU variation's period was 5 minutes or more, and a one minute reporting period was adequate to show the problem. This message reports some specifics from runs with the server on a PC 300PL.
I have looked for this problem on a uniprocessor RS/6000 machine running AIX 4.3.3. There I did not see a clearly defined CPU variation of significant magnitude.
I have run my simple test client and server at various points within the LAN in my office building. The most common configuration involves a box my support people describe as "an ethernet switch with IP routing capability" --- but my client and server are on the same IP subnet. Between each of my machines and the abovementioned "box" is a "smart ethernet hub" or "switch" concentrating 3 or 4 of my machines onto a single connection to that "box". All links are 100 Mb/s ethernet.
I have attached a JPEG of the part of a procmeter3 display covering about three cycles of one run. You see horizontal lines for 0%, 20%, 40%, and 60% CPU utilization. I have procmeter3's reporting period set to 60 seconds, and the CPU variation's period is about 20 minutes.
Here are two excerpts from a run of both the simple server and the `nice`d user-level idle loop, showing very different alleged CPU utilizations by the simple test server and the user-level idle loop --- and their own observations of constant progress:
At Tue Jan 29 16:06:14 2002 + 551771us, dIter=116904, dt=60005989 us db=[ 12.0, 704.90 +- 261.41, 937.0, 82405232.0], I=[ 3.0, 472.41 +- 2730.20, 23828.0, 55226872.0] us, M=[ 19.0, 24.19 +- 109.83, 30051.0, 2827827.0] us, O=[ 2.0, 14.02 +- 61.04, 20065.0, 1639097.0] us, chg-user-t=[0.0, 0.000316 +- 0.017788, 1.0, 37.0] cs, 0.6% chg-syst-t=[0.0, 0.000274 +- 0.016543, 1.0, 32.0] cs, 0.5% chg-both-t=[0.0, 0.000590 +- 0.024288, 1.0, 69.0] cs, 1.1% cum-user-t=70 cs, cum-syst-t=65 cs, cum-both-t=135 cs.
mach user cs nice cs syst cs idle cs total cs cum 130270 56924 88832 8857843 9133869 diff 37 5913 50 0 6000 %age 0.6 98.6 0.8 0.0
At Tue Jan 29 16:06:58 2002 + 682939us, count=1917, d-count=475, d-t=60050540 us, rate=7.91/s
At Tue Jan 29 16:07:14 2002 + 551797us, dIter=117257, dt=60000026 us db=[ 15.0, 704.85 +- 261.43, 937.0, 82648121.0], I=[ 3.0, 471.11 +- 2721.76, 23852.0, 55240914.0] us, M=[ 19.0, 23.90 +- 65.85, 20050.0, 2802985.0] us, O=[ 2.0, 14.08 +- 60.88, 20031.0, 1651205.0] us, chg-user-t=[0.0, 0.000205 +- 0.014305, 1.0, 24.0] cs, 0.4% chg-syst-t=[0.0, 0.000247 +- 0.015725, 1.0, 29.0] cs, 0.5% chg-both-t=[0.0, 0.000452 +- 0.021256, 1.0, 53.0] cs, 0.9% cum-user-t=94 cs, cum-syst-t=94 cs, cum-both-t=188 cs.
mach user cs nice cs syst cs idle cs total cs cum 130294 62858 88873 8857843 9139868 diff 24 5934 41 0 5999 %age 0.4 98.9 0.7 0.0
<snip/>
At Tue Jan 29 16:19:14 2002 + 635582us, dIter=114611, dt=60008078 us db=[ 3.0, 716.20 +- 257.87, 937.0, 82083840.0], I=[ 3.0, 452.13 +- 2663.22, 30133.0, 51819438.0] us, M=[ 19.0, 42.91 +- 649.27, 30165.0, 4918375.0] us, O=[ 2.0, 24.90 +- 484.11, 30148.0, 2853877.0] us, chg-user-t=[0.0, 0.008097 +- 0.089618, 1.0, 928.0] cs, 15.5% chg-syst-t=[0.0, 0.012111 +- 0.109380, 1.0, 1388.0] cs, 23.1% chg-both-t=[0.0, 0.020207 +- 0.140710, 1.0, 2316.0] cs, 38.6% cum-user-t=2567 cs, cum-syst-t=3473 cs, cum-both-t=6040 cs.
mach user cs nice cs syst cs idle cs total cs cum 132768 127512 93745 8857843 9211868 diff 928 3165 1907 0 6000 %age 15.5 52.8 31.8 0.0
At Tue Jan 29 16:19:59 2002 + 677315us, count=8102, d-count=477, d-t=60116853 us, rate=7.93/s
At Tue Jan 29 16:20:14 2002 + 635615us, dIter=114403, dt=60000033 us db=[ 5.0, 718.34 +- 261.50, 937.0, 82180226.0], I=[ 3.0, 451.92 +- 2665.81, 30080.0, 51700975.0] us, M=[ 19.0, 42.83 +- 657.08, 30132.0, 4900343.0] us, O=[ 2.0, 25.24 +- 457.30, 30087.0, 2887847.0] us, chg-user-t=[0.0, 0.009772 +- 0.098372, 1.0, 1118.0] cs, 18.6% chg-syst-t=[0.0, 0.010262 +- 0.100781, 1.0, 1174.0] cs, 19.6% chg-both-t=[0.0, 0.020034 +- 0.140119, 1.0, 2292.0] cs, 38.2% cum-user-t=3685 cs, cum-syst-t=4647 cs, cum-both-t=8332 cs.
mach user cs nice cs syst cs idle cs total cs cum 133886 130615 95523 8857843 9217867 diff 1118 3103 1778 0 5999 %age 18.6 51.7 29.6 0.0
Here is a brief guide to the output. The first two blocks of text you see are from the simple test server, at the end of a reporting period; the third is from the instrumented user-level idle loop at the end of one of its reporting periods. This pattern repeats regularly in the full typescript. The excerpts above focus on two idle loop reports and their surrounding test server reports (because the reporting periods are not aligned). The simple test server begins by reporting the time at the end of the reporting period, with the number of iterations and microseconds since the last report. Then there is a statistical summary of the numbers of bytes input by the read() calls over the last period. The summary's contents are: min, avg +- std.dev., max, sum. Then come statistical summaries of the elapsed times (in microseconds) taken in the three phases of the server's loop body (over the last reporting period): Input, copy & Munge, and Output. Then come statistical summaries of the CPU utilizations reported for the server process by differencing times() for each iteration in the last reporting period; "both" is the sum of the user and system times. The second text block from the simple test server reports the breakdown from the CPU line of /proc/stat: first the raw cumulative numbers, then the differences from the last report, and finally each difference as a percentage of the sum of the differences. The block from the instrumented user-level idle loop reports current and differenced time and outer loop iterations, and then the ratio of the two differences.
In all reports excerpted above, the simple test server says it has echoed about 82 MB over the past approx. 60 seconds, and the user-level idle loop does 476 +- 1 outer loop iterations over the past approx. 60 seconds. But the CPU utilization alleged for the test server varies from about 38% to about 1%, while the idle loop's CPU varies from about 52% to about 99%. I don't have space to include it here, but the procmeter3 display also shows essentially constant network input and output throughput.
When I run the simple test server alone (without the idle loop in parallel), I see no `nice`-level CPU usage, so I know all the `nice` exhibited above is due to my `nice`d user-level idle loop.
[3.] Keywords (i.e., modules, networking, kernel):
networking, kernel, CPU utilization
[4.] Kernel version (from /proc/version):
I have seen this on Linux 2.2.something (RedHat 6.2), 2.4.something (stock RedHat 7.1), 2.4.9-12, and 2.4.9-21 (the latest patch level of RedHat 7.1). For the last, here is /proc/version:
Linux version 2.4.9-21 (bhcompile@stripples.devel.redhat.com) (gcc version 2.96 20000731 (Red Hat Linux 7.1 2.96-98)) #1 Thu Jan 17 14:09:42 EST 2002
[6.] A small shell script or example program which triggers the problem (if possible)
I have attached the sources for the client and server for my simple test service, along with my instrumented user-level idle loop (strip the .txt off the file names before you use them; they are ordinary C and Java sources). On the server machine, here is a compilation and an example usage:
$ cc -o sserver -g sserver.c -lm $ cc -o idle -g idle.c $ ./sserver 60 0 & nice ./idle 60
That invocation asks for a reporting period of 60 seconds in both the simple server and the user-level idle loop. The second parameter of the server program gives the number of iterations of an inner loop that can be used to bulk up the CPU consumption; it's not needed to show the effect, and a value of 0 cuts it out. The server program reports the ephemeral port number on which it is listening for connections; you'll need to pass that to the client program.
The client test program is written in Java. It should compile and run with any non-antique Java; I use IBM's JDK 1.3.0. Put the client source in test/client.java; here's an example of compilation and usage:
$ javac test/client.java $ java test.client eutil2 32800 1 10 20 25000
There "eutil2" is the name of the machine running the server, and "32800" is the port on which it is listening (your number will vary). "1" restricts the client to one connection at a time (necessary for this very simple test server). On each iteration, the client picks (uniform random choice) a sleep time from a given interval, 10--20 milliseconds in this case. The length of the buffer written is specified above to be 25000 bytes.
You probably want to run the client and server on different machines; the one time I tried them both on the same machine the period was about 4 days.
[7.] Environment
[7.1.] Software (add the output of the ver_linux script here)
[root@eutil2 linux-2.4.9-21]# sh scripts/ver_linux If some fields are empty or look unusual you may have an old version. Compare to the current minimal requirements in Documentation/Changes. Linux eutil2.watson.ibm.com 2.4.9-21 #1 Thu Jan 17 14:09:42 EST 2002 i686 unknown Gnu C 2.96 Gnu make 3.79.1 binutils 2.10.91.0.2 util-linux 2.11f mount 2.11b modutils 2.4.10 e2fsprogs 1.23 PPP 2.4.0 isdn4k-utils 3.1pre1 Linux C Library 2.2.4 Dynamic linker (ldd) 2.2.4 Procps 2.0.7 Net-tools 1.57 Console-tools 0.3.3 Sh-utils 2.0 Modules Loaded autofs 3c59x ipchains usb-uhci usbcore
[7.2.] Processor information (from /proc/cpuinfo):
[tstusr@eutil2 tstusr]$ cat /proc/cpuinfo processor : 0 vendor_id : GenuineIntel cpu family : 6 model : 8 model name : Pentium III (Coppermine) stepping : 3 cpu MHz : 662.226 cache size : 256 KB fdiv_bug : no hlt_bug : no f00f_bug : no coma_bug : no fpu : yes fpu_exception : yes cpuid level : 2 wp : yes flags : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 mmx fxsr sse bogomips : 1320.55
[7.3.] Module information (from /proc/modules):
[tstusr@eutil2 tstusr]$ cat /proc/modules autofs 11300 2 (autoclean) 3c59x 25224 1 (autoclean) ipchains 36424 0 usb-uhci 20708 0 (unused) usbcore 49920 1 [usb-uhci]
[7.4.] Loaded driver and hardware information (/proc/ioports, /proc/iomem)
[tstusr@eutil2 tstusr]$ cat /proc/ioports 0000-001f : dma1 0020-003f : pic1 0040-005f : timer 0060-006f : keyboard 0070-007f : rtc 0080-008f : dma page reg 00a0-00bf : pic2 00c0-00df : dma2 00f0-00ff : fpu 0170-0177 : ide1 01f0-01f7 : ide0 02f8-02ff : serial(auto) 0376-0376 : ide1 03c0-03df : vga+ 03f6-03f6 : ide0 03f8-03ff : serial(auto) 0cf8-0cff : PCI conf1 7480-74ff : 3Com Corporation 3c905B 100BaseTX [Cyclone] 7480-74ff : 00:0f.0 7800-78ff : ESS Technology ES1988 Allegro-1 fce0-fcff : VIA Technologies, Inc. UHCI USB fce0-fcff : usb-uhci fff0-ffff : VIA Technologies, Inc. Bus Master IDE fff0-fff7 : ide0 fff8-ffff : ide1
[tstusr@eutil2 tstusr]$ cat /proc/iomem 00000000-0009fbff : System RAM 0009fc00-0009ffff : reserved 000a0000-000bffff : Video RAM area 000c0000-000c7fff : Video ROM 000f0000-000fffff : System ROM 00100000-0ffe2ebf : System RAM 00100000-002b2cab : Kernel code 002b2cac-002c986b : Kernel data 0ffe2ec0-0ffe6ebf : ACPI Tables 0ffe6ec0-0ffeeeff : ACPI Non-volatile Storage 0ffeef00-0fffffff : reserved ec000000-efffffff : VIA Technologies, Inc. VT82C693A/694x [Apollo PRO133x] f0000000-fe9fffff : PCI Bus #01 f0000000-f7ffffff : S3 Inc. Savage 4 feafff80-feafffff : 3Com Corporation 3c905B 100BaseTX [Cyclone] feb00000-febfffff : PCI Bus #01 feb80000-febfffff : S3 Inc. Savage 4 fec00000-fec00fff : reserved fee00000-fee00fff : reserved fff80000-ffffffff : reserved
[7.5.] PCI information ('lspci -vvv' as root)
[root@eutil2 /root]# lspci -vvv 00:00.0 Host bridge: VIA Technologies, Inc. VT82C691 [Apollo PRO] (rev c4) Control: I/O- Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B- Status: Cap+ 66Mhz- UDF- FastB2B- ParErr- DEVSEL=medium >TAbort- <TAbort- <MAbort+ >SERR- <PERR+ Latency: 8 Region 0: Memory at ec000000 (32-bit, prefetchable) [size=64M] Capabilities: [a0] AGP version 2.0 Status: RQ=31 SBA+ 64bit- FW- Rate=x1,x2 Command: RQ=0 SBA- AGP- 64bit- FW- Rate=<none> Capabilities: [c0] Power Management version 2 Flags: PMEClk- DSI- D1- D2- AuxCurrent=0mA PME(D0-,D1-,D2-,D3hot-,D3cold-) Status: D0 PME-Enable- DSel=0 DScale=0 PME-
00:01.0 PCI bridge: VIA Technologies, Inc. VT82C598/694x [Apollo MVP3/Pro133x AGP] (prog-if 00 [Normal decode]) Control: I/O+ Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B- Status: Cap+ 66Mhz+ UDF- FastB2B- ParErr- DEVSEL=medium >TAbort- <TAbort- <MAbort+ >SERR- <PERR- Latency: 0 Bus: primary=00, secondary=01, subordinate=01, sec-latency=0 I/O behind bridge: 0000f000-00000fff Memory behind bridge: feb00000-febfffff Prefetchable memory behind bridge: f0000000-fe9fffff BridgeCtl: Parity- SERR- NoISA+ VGA+ MAbort- >Reset- FastB2B- Capabilities: [80] Power Management version 2 Flags: PMEClk- DSI- D1- D2- AuxCurrent=0mA PME(D0-,D1-,D2-,D3hot-,D3cold-) Status: D0 PME-Enable- DSel=0 DScale=0 PME-
00:02.0 ISA bridge: VIA Technologies, Inc. VT82C596 ISA [Mobile South] (rev 12) Control: I/O+ Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping+ SERR- FastB2B- Status: Cap- 66Mhz- UDF- FastB2B- ParErr- DEVSEL=medium >TAbort- <TAbort- <MAbort- >SERR- <PERR- Latency: 0
00:02.1 IDE interface: VIA Technologies, Inc. Bus Master IDE (rev 06) (prog-if 8a [Master SecP PriP]) Control: I/O+ Mem- BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping+ SERR- FastB2B- Status: Cap- 66Mhz- UDF- FastB2B+ ParErr- DEVSEL=medium >TAbort- <TAbort- <MAbort- >SERR- <PERR- Latency: 32 Region 4: I/O ports at fff0 [size=16]
00:02.2 USB Controller: VIA Technologies, Inc. UHCI USB (rev 08) (prog-if 00 [UHCI]) Subsystem: Unknown device 0925:1234 Control: I/O+ Mem- BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B- Status: Cap- 66Mhz- UDF- FastB2B- ParErr- DEVSEL=medium >TAbort- <TAbort- <MAbort- >SERR- <PERR- Latency: 22 Interrupt: pin D routed to IRQ 10 Region 4: I/O ports at fce0 [size=32]
00:02.3 Host bridge: VIA Technologies, Inc. VT82C596 Power Management (rev 20) Control: I/O- Mem- BusMaster- SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B- Status: Cap- 66Mhz- UDF- FastB2B+ ParErr- DEVSEL=medium >TAbort- <TAbort- <MAbort- >SERR- <PERR-
00:0f.0 Ethernet controller: 3Com Corporation 3c905B 100BaseTX [Cyclone] (rev 30) Subsystem: 3Com Corporation 3C905B Fast Etherlink XL 10/100 Control: I/O+ Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR+ FastB2B- Status: Cap+ 66Mhz- UDF- FastB2B- ParErr- DEVSEL=medium >TAbort- <TAbort- <MAbort- >SERR- <PERR- Latency: 80 (2500ns min, 2500ns max), cache line size 08 Interrupt: pin A routed to IRQ 9 Region 0: I/O ports at 7480 [size=128] Region 1: Memory at feafff80 (32-bit, non-prefetchable) [size=128] Expansion ROM at ff000000 [disabled] [size=128K] Capabilities: [dc] Power Management version 1 Flags: PMEClk- DSI- D1+ D2+ AuxCurrent=0mA PME(D0-,D1+,D2+,D3hot+,D3cold+) Status: D0 PME-Enable+ DSel=0 DScale=0 PME-
00:12.0 Multimedia audio controller: ESS Technology ES1988 Allegro-1 (rev 10) Subsystem: IBM: Unknown device 017b Control: I/O+ Mem- BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B- Status: Cap+ 66Mhz- UDF- FastB2B+ ParErr- DEVSEL=medium >TAbort- <TAbort- <MAbort- >SERR- <PERR- Latency: 16 (500ns min, 6000ns max) Interrupt: pin A routed to IRQ 5 Region 0: I/O ports at 7800 [size=256] Capabilities: [c0] Power Management version 2 Flags: PMEClk- DSI+ D1+ D2+ AuxCurrent=0mA PME(D0-,D1+,D2+,D3hot+,D3cold-) Status: D0 PME-Enable+ DSel=0 DScale=0 PME-
01:00.0 VGA compatible controller: S3 Inc. Savage 4 (rev 04) (prog-if 00 [VGA]) Subsystem: Diamond Multimedia Systems: Unknown device 4906 Control: I/O+ Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B- Status: Cap+ 66Mhz+ UDF- FastB2B- ParErr- DEVSEL=medium >TAbort- <TAbort- <MAbort- >SERR- <PERR- Latency: 248 (1000ns min, 63750ns max), cache line size 08 Interrupt: pin A routed to IRQ 11 Region 0: Memory at feb80000 (32-bit, non-prefetchable) [size=512K] Region 1: Memory at f0000000 (32-bit, prefetchable) [size=128M] Expansion ROM at <unassigned> [disabled] [size=64K] Capabilities: [dc] Power Management version 1 Flags: PMEClk- DSI+ D1+ D2+ AuxCurrent=0mA PME(D0-,D1-,D2-,D3hot-,D3cold-) Status: D0 PME-Enable- DSel=0 DScale=0 PME- Capabilities: [80] AGP version 2.0 Status: RQ=31 SBA- 64bit- FW- Rate=x1,x2 Command: RQ=0 SBA- AGP- 64bit- FW- Rate=<none>
[7.6.] SCSI information (from /proc/scsi/scsi)
There is no /proc/scsi.
[7.7.] Other information that might be relevant to the problem (please look in /proc and include all information that you think to be relevant):
For information on procmeter3, see <http://www.gedanken.demon.co.uk/procmeter3/>.
I don't think the problem depends on the client's JDK, but just for completeness:
[tstusr@eutil2 tstusr]$ java -version java version "1.3.0" Java(TM) 2 Runtime Environment, Standard Edition (build 1.3.0) Classic VM (build 1.3.0, J2RE 1.3.0 IBM build cx130-20010925 (JIT enabled: jitc))
Thank you, and I hope you find this useful, Mike #include <stdlib.h> /* for atoi, malloc */ #include <stdio.h> #include <math.h> /* for sqrt() */ #include <unistd.h> /* for read, write, getpid */ #include <errno.h> /* for errno */ #include <time.h> /* for ctime() */ #include <sys/time.h> /* for gettimeofday() */ #include <sys/times.h> /* for times() */ #include <sys/types.h> /* for socket(), getpid, etc */ #include <sys/socket.h> /* for socket(), etc */ #include <netinet/in.h> /* for sockaddr_in, in_addr */
#define MYBUFLEN 937
typedef struct { struct sockaddr_in remaddr; int sock; char *cbuf; char *wbuf; } ConnData;
typedef struct { double ss_min, ss_max, ss_sum1, ss_sum2; } StatSum;
typedef struct { long unsigned psc_user, psc_nice, psc_syst, psc_idle, psc_total; } ProcStatCpu;
typedef struct { int ps_utime; int ps_stime; int ps_ttime; } ProcsStat;
#define ZSS {10*1000*1000, 0, 0, 0.0} static StatSum zss = ZSS;
void updateSSd(StatSum *ss, double x) { ss->ss_sum1 += x; ss->ss_sum2 += x*x; if (x < ss->ss_min) ss->ss_min = x; if (x > ss->ss_max) ss->ss_max = x; return; }
void updateSS(StatSum *ss, long x) {updateSSd(ss, (double)x);}
char *sfmtSS(char *buf, StatSum ss, long nIter, int fmti) { double n = nIter; double avg = ((double)ss.ss_sum1) / n; double devsq = 0; if (nIter > 1) devsq = ((ss.ss_sum2 + n*avg*avg - 2*avg*ss.ss_sum1) / (n-1)); if (devsq >= 0) sprintf(buf, (fmti ?"[%3.1f, %8.6f += %8.6f, %3.1f, %6.1f]" :"[%6.1f, %7.2f += %7.2f, %7.1f, %10.1f]"), ss.ss_min, avg, (double) sqrt(devsq), ss.ss_max, ss.ss_sum1); else sprintf(buf, (fmti ?"[%3.1f, %8.6f += sqrt(%8.6f), %3.1f, %6.1f]" :"[%6.1f, %7.2f += sqrt(%7.2f), %7.1f, %10.1f]"), ss.ss_min, avg, devsq, ss.ss_max, ss.ss_sum1); return buf; }
char *sfmtTime(char *buf, struct timeval tv) { char *tstr; tstr = ctime(&tv.tv_sec); if (tstr != NULL) { int tslen; tslen = strlen(tstr); if (tstr[tslen-1] == '\n') tstr[tslen-1] = 0; sprintf(buf, "%s + %06ldus", tstr, (long) tv.tv_usec); } else sprintf(buf, "%ld + %06ldus (ctime failed)", (long) tv.tv_sec, (long) tv.tv_usec); return buf; }
char *sfmtNow(char *buf) { struct timeval now; int res; res = gettimeofday(&now, NULL); if (res) sprintf(buf, "(getttimeofday() failed!)"); else sfmtTime(buf, now); return buf; }
long dtv(struct timeval tva, struct timeval tvb) { long ds = tva.tv_sec - tvb.tv_sec ; long dus = tva.tv_usec - tvb.tv_usec; return (dus + (1000000*ds)); }
long ReportPeriod_S = 60; int fusum; struct timeval lastRept = {0}; StatSum dBytes = ZSS, dusIn = ZSS, dusMid = ZSS, dusOut = ZSS; StatSum dut = ZSS, dst = ZSS, dbt = ZSS;
ProcStatCpu curPsc; ProcsStat curPs; FILE *procStat = NULL, *procsStat = NULL;
int pid;
ProcStatCpu readProcStat() { int ns; ProcStatCpu ans; rewind(procStat); ns = fscanf(procStat, "cpu %lu %lu %lu %lu\n", &ans.psc_user, &ans.psc_nice, &ans.psc_syst, &ans.psc_idle); if (ns != 4) { fprintf(stderr, "Read of /proc/stat failed!\n"); exit(1); } ans.psc_total = (ans.psc_user + ans.psc_nice + ans.psc_syst + ans.psc_idle); return ans; }
ProcsStat readProcsStat() { int ns; ProcsStat ans; rewind(procsStat); ns = fscanf(procsStat, "%*d (%*s %*c %*d %*d %*d %*d %*d %*u %*u %*u %*u %*u %d %d ", &ans.ps_utime, &ans.ps_stime); if (ns < 2) { fprintf(stderr, "proc's stat scanf failed!\n"); exit(1); } ans.ps_ttime = ans.ps_utime + ans.ps_stime; return ans; }
ProcStatCpu psc_diff(ProcStatCpu *pa, ProcStatCpu *pb) { ProcStatCpu ans; ans.psc_user = pa->psc_user - pb->psc_user; ans.psc_nice = pa->psc_nice - pb->psc_nice; ans.psc_syst = pa->psc_syst - pb->psc_syst; ans.psc_idle = pa->psc_idle - pb->psc_idle; ans.psc_total = pa->psc_total - pb->psc_total; return ans; }
void psc_printStep(char *what, ProcStatCpu *pCur, ProcStatCpu *pNxt) { ProcStatCpu dltPsc; float tot, pct_user, pct_nice, pct_syst, pct_idle; dltPsc = psc_diff(pNxt, pCur); tot = dltPsc.psc_total; pct_user = 100 * dltPsc.psc_user / tot; pct_nice = 100 * dltPsc.psc_nice / tot; pct_syst = 100 * dltPsc.psc_syst / tot; pct_idle = 100 * dltPsc.psc_idle / tot; printf("%s\tuser cs\tnice cs\tsyst cs\t idle cs\t total cs\n" "cum\t%7lu\t%7lu\t%7lu\t%10lu\t%10lu\n" "diff\t%7lu\t%7lu\t%7lu\t%10lu\t%10lu\n" "%%age\t%7.1f\t%7.1f\t%7.1f\t%10.1f\n\n", what , pNxt->psc_user, pNxt->psc_nice , pNxt->psc_syst, pNxt->psc_idle , pNxt->psc_total , dltPsc.psc_user, dltPsc.psc_nice , dltPsc.psc_syst, dltPsc.psc_idle , dltPsc.psc_total , pct_user, pct_nice, pct_syst, pct_idle ); }
void ps_printStep(int pid, ProcsStat *pCur, ProcsStat *pNxt, float dt) { int dutime = pNxt->ps_utime - pCur->ps_utime; int dstime = pNxt->ps_stime - pCur->ps_stime; int dttime = pNxt->ps_ttime - pCur->ps_ttime; float pct_u = 1.0 * dutime / dt; float pct_s = 1.0 * dstime / dt; float pct_t = 1.0 * dttime / dt; printf("p%d\tuser\tkern\tboth\n" "new\t%d\t%d\t%d\n" "diff\t%d\t%d\t%d\n" "%%age\t%04.1f\t%04.1f\t%04.1f\n", pid , pNxt->ps_utime, pNxt->ps_stime, pNxt->ps_ttime , dutime, dstime, dttime , pct_u, pct_s, pct_t ); }
void *runConn(void *arg, int nsub) { ConnData *cdp = (ConnData*) arg; char *wbuf; size_t i; int j, res; long sinceRept, dIter = 0, ReportPeriod_US = ReportPeriod_S*1000*1000; struct timeval tvb, tva; struct tms tmsa, tmsb; int first; char bufb[100], bufi[100], bufm [100], bufo[100]; char bufu[100], bufs[100], bufus[100], buft[100]; if (times(&tmsa) == (clock_t) -1) { fprintf(stderr, "times() A failed.\n"); exit(13); } if (procStat) curPsc = readProcStat(); if (procsStat) curPs = readProcsStat(); res = gettimeofday(&tva, NULL); if (res != 0) exit(22); lastRept = tva; for (;1;) { ssize_t nb, nbw; res = gettimeofday(&tvb, NULL); if (res != 0) exit(21); nb = read(cdp->sock, cdp->cbuf, MYBUFLEN); if (nb < 0) { int theErr = errno; fprintf(stderr, "At %s, aborting conn at read, errno=%d.\n", sfmtNow(buft), theErr); return; } if (nb == 0) { fprintf(stderr, "got EOF.\n"); exit(0); /* so gprof writes its stats */ } res = gettimeofday(&tva, NULL); if (res != 0) exit(22); updateSS(&dusIn, dtv(tva, tvb)); updateSS(&dBytes, (long) nb); cdp->cbuf[MYBUFLEN] = 0; for (i = 0; i <= MYBUFLEN; i++) { cdp->wbuf[i] = cdp->cbuf[i]; } for (j = 0; j < nsub; j++) { for (i=0; i < MYBUFLEN; i++) { int dm, n, q; dm = cdp->wbuf[MYBUFLEN-i]; n = cdp->cbuf[(i+400*j)%MYBUFLEN]; q = n / (dm + 1); fusum += q; } } if (fusum == 123456789) fprintf(stdout, "Bingo!\n"); res = gettimeofday(&tvb, NULL); if (res != 0) exit(23); updateSS(&dusMid, dtv(tvb, tva)); for (wbuf = cdp->wbuf; nb > 0; ) { nbw = write(cdp->sock, wbuf, nb); if (nbw < 0) { int theErr = errno; fprintf(stderr, "At %s, aborting conn at write, errno=%d.\n", sfmtNow(buft), theErr); return; } nb -= nbw; wbuf += nbw; } res = gettimeofday(&tva, NULL); if (res != 0) exit(24); if (times(&tmsb) == (clock_t) -1) { fprintf(stderr, "times() B failed.\n"); exit(25); } updateSS (&dusOut, dtv(tva, tvb)); /* updateSSd(&dut, ((double) (tmsb.tms_utime - tmsa.tms_utime))/CLOCKS_PER_SEC); updateSSd(&dst, ((double) (tmsb.tms_stime - tmsa.tms_stime))/CLOCKS_PER_SEC); */ updateSS(&dut, (tmsb.tms_utime - tmsa.tms_utime) ); updateSS(&dst, (tmsb.tms_stime - tmsa.tms_stime) ); updateSS(&dbt, ((tmsb.tms_utime - tmsa.tms_utime) + (tmsb.tms_stime - tmsa.tms_stime))); tmsa = tmsb; sinceRept = dtv(tva, lastRept); dIter++; if (sinceRept >= ReportPeriod_US) { ProcStatCpu nxtPsc, dltPsc; ProcsStat nxtPs; float pct_u = dut.ss_sum1*1.0e6/sinceRept; float pct_s = dst.ss_sum1*1.0e6/sinceRept; float pct_b = dbt.ss_sum1*1.0e6/sinceRept; if (procStat) { nxtPsc = readProcStat(); } if (procsStat) { nxtPs = readProcsStat(); } printf("\n\nAt %s, dIter=%ld, dt=%ld us\n" "db=%s,\n" "I=%s us,\nM=%s us,\nO=%s us,\n" "chg-user-t=%s cs, %4.1f%%\n" "chg-syst-t=%s cs, %4.1f%%\n" "chg-both-t=%s cs, %4.1f%%\n" "cum-user-t=%ld cs, cum-syst-t=%ld cs, cum-both-t=%ld cs.\n" "\n", sfmtTime(buft, tva), dIter, sinceRept, sfmtSS(bufb, dBytes, dIter, 0), sfmtSS(bufi, dusIn , dIter, 0), sfmtSS(bufm, dusMid, dIter, 0), sfmtSS(bufo, dusOut, dIter, 0), sfmtSS(bufu , dut , dIter, 1), pct_u, sfmtSS(bufs , dst , dIter, 1), pct_s, sfmtSS(bufus, dbt , dIter, 1), pct_b, (long) tmsb.tms_utime, (long) tmsb.tms_stime, (long) tmsb.tms_utime + tmsb.tms_stime ); dBytes = dusIn = dusMid = dusOut = dut = dst = dbt = zss; dIter = 0; lastRept = tva; if (procStat) { psc_printStep("mach", &curPsc, &nxtPsc); curPsc = nxtPsc; } if (procsStat) { ps_printStep(pid, &curPs, &nxtPs, sinceRept/1.0e6); curPs = nxtPs ; } } } }
int main(int argc, char **argv) { int ss; int port; union { struct sockaddr mysa; struct sockaddr_in mysain; } mysau; int salen = sizeof(mysau.mysa); int res; int nsub = 1; pid_t tpid; if (argc != 3) { fprintf(stderr, "Usage: %s report-period n-sub\n", argv[0]); return 1; } ReportPeriod_S = atoi(argv[1]); nsub = atoi(argv[2]); fprintf(stdout, "Report Period = %ld seconds\n", ReportPeriod_S); fprintf(stdout, "Sub loop count = %d\n", nsub); fprintf(stdout, "CLOCKS_PER_SEC = %g\n", (double) CLOCKS_PER_SEC); fusum = 0; tpid = getpid(); pid = tpid; ss = socket(AF_INET, SOCK_STREAM, 0); if (ss < 0) { int theErr = errno; fprintf(stderr, "socket() failed, errno=%d.\n", theErr); exit(2); } res = listen(ss, 100); if (res < 0) { int theErr = errno; fprintf(stderr, "listen() failed, errno=%d.\n", theErr); exit(4); } res = getsockname(ss, &mysau.mysa, &salen); if (res < 0) { int theErr = errno; fprintf(stderr, "getsockname() failed, errno=%d.\n", theErr); exit(6); } if (salen != sizeof(mysau.mysain)) { fprintf(stderr, "getsockname() returned len=%d rather than %d.\n", salen, sizeof(mysau.mysain)); exit(8); } port = ntohs(mysau.mysain.sin_port); fprintf(stdout, "listening on port %d.\n", port); procStat = fopen("/proc/stat", "r"); if (!procStat){ fprintf(stderr, "Failed to open /proc/stat!\n"); } else { setvbuf(procStat , NULL, _IONBF, 0); } if (0) { char psname[100]; sprintf(psname, "/proc/%d/stat", pid); procsStat = fopen(psname, "r"); if (!procsStat) { fprintf(stderr, "Failed to open proc %d's stat!\n", pid); } else { setvbuf(procsStat, NULL, _IONBF, 0); } } for (;;) { int newsock; ConnData *cdp; salen = sizeof(mysau.mysa); newsock = accept(ss, &mysau.mysa, &salen); if (newsock < 0) { int theErr = errno; fprintf(stderr, "accept() failed, errno=%d.\n", theErr); exit(10); } if (salen != sizeof(mysau.mysain)) { fprintf(stderr, "accept claimed remote address of length %d, rather than %d.\n", salen, sizeof(mysau.mysain)); exit(12); } cdp = (ConnData*) malloc(sizeof(ConnData)); if (cdp != NULL) { cdp->cbuf = malloc(MYBUFLEN+1); cdp->wbuf = malloc(MYBUFLEN+1); } if (cdp == NULL || cdp->cbuf==NULL || cdp->wbuf==NULL) { fprintf(stderr, "malloc failed!\n"); exit(14); } cdp->remaddr = mysau.mysain; cdp->sock = newsock; runConn(cdp, nsub); } }#include <stdio.h> #include <stdlib.h> #include <time.h> #include <sys/time.h>
long unsigned countInner;
char *sfmtTime(char *buf, struct timeval tv) { char *tstr; tstr = ctime(&tv.tv_sec); if (tstr != NULL) { int tslen; tslen = strlen(tstr); if (tstr[tslen-1] == '\n') tstr[tslen-1] = 0; sprintf(buf, "%s + %06ldus", tstr, (long) tv.tv_usec); } else sprintf(buf, "%ld + %06ldus (ctime failed)", (long) tv.tv_sec, (long) tv.tv_usec); return buf; }
long dtv(struct timeval tva, struct timeval tvb) { long ds = tva.tv_sec - tvb.tv_sec ; long dus = tva.tv_usec - tvb.tv_usec; return (dus + (1000000*ds)); }
void inner() { int i; for (i = 0; i < 10000000; i++) countInner ++; return; }
int main(int argc, char **argv) { long unsigned countOuter, lastCount = 0; struct timeval tva, tvb; int res, ReportPeriod_S, ReportPeriod_US; long since; char buft[100]; if (argc != 2) { fprintf(stderr, "Usage: %s report-period\n", argv[0]); return 1; } ReportPeriod_S = atoi(argv[1]); ReportPeriod_US = ReportPeriod_S * 1000 * 1000; fprintf(stdout, "Report Period = %g seconds\n", ReportPeriod_US/(double)1.0e6); res = gettimeofday(&tva, NULL); if (res != 0) exit(22); for (countOuter = 0; ; countOuter++) { inner(); res = gettimeofday(&tvb, NULL); if (res != 0) exit(22); since = dtv(tvb, tva); if (since > ReportPeriod_US) { long unsigned dCount = countOuter - lastCount; float rate = dCount * 1.0e6 / since; printf("At %s, count=%lu,\n" "d-count=%lu, d-t=%ld us, rate=%4.2f/s\n", sfmtTime(buft, tvb), countOuter, dCount, since, rate); lastCount = countOuter; tva = tvb; } } }[unhandled content-type:image/jpeg]package test;
import java.io.*; import java.net.*; import java.util.Date; import java.text.DateFormat; import java.util.Random;
public class client {
Socket s; int pauseMillisMin, pauseMillisMax; int msgLen; String msg;
Random rand = new Random();
public client(InetAddress host, int sport, int pauseMillisMin, int pauseMillisMax, int msgLen) throws IOException { s = new Socket(host, sport); this.pauseMillisMin = pauseMillisMin; this.pauseMillisMax = pauseMillisMax; this.msgLen = msgLen; StringBuffer sb = new StringBuffer(msgLen+1); for (int i = 0; i < msgLen; i++) sb.append((char) (33 + Math.random()*93)); sb.append("\n"); msg = sb.toString(); (new Thread(new MyWriter(s.getOutputStream()))).start(); (new Thread(new MyReader(s.getInputStream()))).start(); }
class MyWriter implements Runnable { OutputStream so; int pauseMillisSpread = 1 + pauseMillisMax - pauseMillisMin; MyWriter(OutputStream so) {this.so = so;} public void run() { OutputStreamWriter osr = new OutputStreamWriter(so); try { while (true) { osr.write(msg); int pauseMillis = pauseMillisMin; if (pauseMillisSpread > 1) pauseMillis += rand.nextInt(pauseMillisSpread); try { Thread.sleep(pauseMillis); } catch (Exception ex) {} } } catch (IOException ex) { int locport = s.getLocalPort(); System.err.println("At " + nowString() + ", aborting writing from " + locport + " because of exn " + ex.getClass().getName() + " msg=" + ex.getMessage()); } } } class MyReader implements Runnable { InputStream si; MyReader(InputStream si) {this.si = si;} public void run() { InputStreamReader isr = new InputStreamReader(si); BufferedReader br = new BufferedReader(isr); try { while (true) { String mr = br.readLine(); if (!msg.regionMatches(0, mr, 0, msgLen)) { System.err.println("Message mismatch! Sent [" + msg + "] received [" + mr + "]."); return; } } } catch (IOException ex) { int locport = s.getLocalPort(); System.err.println("At " + nowString() + ", aborting reading through " + locport + " because of exn " + ex.getClass().getName() + " msg=" + ex.getMessage()); } } } public static void main(String[] args) throws IOException { if (args.length != 6) { System.err.println("Usage: client host port nThreads pauseMillisMin pauseMillisMax msgLen"); System.exit(1); } String hostStr = args[0]; int sport = Integer.parseInt(args[1]); int nThreads = Integer.parseInt(args[2]); int pauseMillisMin = Integer.parseInt(args[3]); int pauseMillisMax = Integer.parseInt(args[4]); int msgLen = Integer.parseInt(args[5]); InetAddress host = InetAddress.getByName(hostStr); System.out.println("Testing host " + host + ", port " + sport + ", n-thds=" + nThreads + ", pause-ms=[" + pauseMillisMin + ", " + pauseMillisMax + "]" + ", msglen=" + msgLen); for (int i = 0; i < nThreads; i++) { new client(host, sport, pauseMillisMin, pauseMillisMax, msgLen); } System.out.println("Started at " + nowString()); }
private static final DateFormat df = DateFormat.getDateTimeInstance(DateFormat.FULL, DateFormat.FULL);
private static String nowString() { Date dNow = new Date(); return df.format(dNow); } } | |