Project

General

Profile

Bug #1333 » power_cpu_issue_PLUS_44hours.txt

Jon Strabala, 2011-09-01 07:02 PM

 
1
root@lab10:~# date
2
September  1, 2011 11:45:06 AM PDT
3

    
4

    
5
root@lab10:~# tail -4 /etc/system
6
* August 30, 2011 02:26:39 PM PDT
7
* try to solve CPU creep issue
8
* https://defect.opensolaris.org/bz/show_bug.cgi?id=12799
9
set cpupm_tw_gov_interval=800000
10

    
11

    
12

    
13
root@lab10:~# rup lab10
14
          lab10    up  1 day,  20:00,    load average: 0.01, 0.00, 0.00
15

    
16

    
17
root@lab10:~# uname -a
18
SunOS lab10 5.11 oi_148b i86pc i386 i86pc Solaris
19
root@lab10:~#
20
root@lab10:~#
21

    
22
root@lab10:~#  prstat -s cpu -n 5 > /tmp/prstat.s.cpu.n.5.out
23
^C
24
root@lab10:~# cat /tmp/prstat.s.cpu.n.5.out
25
   PID USERNAME  SIZE   RSS STATE  PRI NICE      TIME  CPU PROCESS/NLWP
26
  1204 root       59M   36M sleep   59    0   0:08:26 0.0% Xorg/3
27
  1657 gdm        87M   25M sleep   59    0   0:00:53 0.0% gdm-simple-gree/1
28
    10 root       16M   13M sleep   59    0   0:00:02 0.0% svc.startd/16
29
   894 root     6968K 5848K sleep   59    0   0:00:04 0.0% intrd/1
30
     1 root     2728K 1860K sleep   59    0   0:00:00 0.0% init/1
31
Total: 64 processes, 390 lwps, load averages: 0.00, 0.00, 0.00
32
   PID USERNAME  SIZE   RSS STATE  PRI NICE      TIME  CPU PROCESS/NLWP
33
  1204 root       59M   36M sleep   59    0   0:08:26 0.0% Xorg/3
34
  1657 gdm        87M   25M sleep   59    0   0:00:53 0.0% gdm-simple-gree/1
35
    10 root       16M   13M sleep   59    0   0:00:02 0.0% svc.startd/16
36
   894 root     6968K 5848K sleep   59    0   0:00:04 0.0% intrd/1
37
     1 root     2728K 1860K sleep   59    0   0:00:00 0.0% init/1
38
Total: 64 processes, 390 lwps, load averages: 0.00, 0.00, 0.00
39
   PID USERNAME  SIZE   RSS STATE  PRI NICE      TIME  CPU PROCESS/NLWP
40
  1204 root       59M   36M sleep   58    0   0:08:26 0.0% Xorg/3
41
  1657 gdm        87M   25M sleep   59    0   0:00:53 0.0% gdm-simple-gree/1
42
    10 root       16M   13M sleep   59    0   0:00:02 0.0% svc.startd/16
43
   894 root     6968K 5848K sleep   59    0   0:00:04 0.0% intrd/1
44
     1 root     2728K 1860K sleep   59    0   0:00:00 0.0% init/1
45
Total: 64 processes, 390 lwps, load averages: 0.00, 0.00, 0.00
46

    
47

    
48

    
49
root@lab10:~# mpstat 5 2
50
CPU minf mjf xcal  intr ithr  csw icsw migr smtx  srw syscl  usr sys  wt idl
51
  0    0   0    0   510  101   74    0    1    0    0    11    0   4   0  96
52
  1    0   0    0    78   10   37    0    1    0    0    11    0   1   0  99
53
  2    1   0    0    74    9   37    0    1    0    0     9    0   1   0  99
54
  3    0   0    0    71    8   35    0    1    0    0     7    0   1   0  99
55
  4    1   0    0    76    9   39    0    1    0    0    10    0   1   0  99
56
  5    1   0    1    70    7   35    0    1    0    0     8    0   1   0  99
57
  6    1   0    0    71    7   35    0    1    0    0     8    0   1   0  99
58
  7    0   0    0    73    7   36    0    1    0    0     7    0   1   0  99
59
CPU minf mjf xcal  intr ithr  csw icsw migr smtx  srw syscl  usr sys  wt idl
60
  0    4   0    0   519  101   86    0    2    0    0    61    0   7   0  93
61
  1    0   0    0    78    9   34    0    2    0    0     7    0   1   0  99
62
  2    0   0    0    80    9   34    0    1    0    0    10    0   1   0  99
63
  3    0   0    0    51    5   25    0    1    0    0     0    0   1   0  99
64
  4    0   0    0    86   12   43    0    1    0    0     0    0   1   0  99
65
  5    0   0    0    91    4   43    0    1    0    0     0    0   1   0  99
66
  6    0   0    0    93   13   47    0    1    0    0    13    0   1   0  98
67
  7    0   0    0    23    0    9    0    1    0    0     2    0   0   0 100
68
root@lab10:~#
69

    
70

    
71

    
72

    
73
root@lab10:~# powertop
74
OpenIndiana PowerTOP version 1.2   (C) 2009 Intel Corporation
75

    
76
Collecting data for 5.00 second(s)
77

    
78
root@lab10:~# vi /tmp/power.top.out
79
root@lab10:~# cat  /tmp/power.top.out
80
                                                    OpenIndiana PowerTOP version 1.2
81

    
82
C-states (idle power)   Avg     Residency                                   P-states (frequencies)
83
C0 (cpu running)                (3.4%)                                      1600 Mhz        0.0%
84
C1                      0.0ms   (0.0%)                                      1800 Mhz        0.0%
85
C2                      0.0ms   (0.0%)                                      2000 Mhz        0.0%
86
C3                      2.4ms   (96.6%)                                     2200 Mhz        0.0%
87
                                                                            2400 Mhz        0.0%
88
                                                                            2600 Mhz        0.0%
89
                                                                            2800 Mhz        0.0%
90
                                                                            3000 Mhz        0.0%
91
                                                                            3200 Mhz        0.0%
92
                                                                            3400 Mhz        0.0%
93
                                                                            3604 Mhz(turbo) 100.0%
94

    
95
Wakeups-from-idle per second: 3201.6    interval: 5.0s
96
no ACPI power usage estimate available
97

    
98
Top causes for wakeups:
99
89.0% (2849.0)                 sched :  <xcalls> unix`dtrace_xcall_func
100
 3.1% (100.0)               <kernel> :  genunix`clock
101
 2.4% ( 76.0)               <kernel> :  genunix`cv_wakeup
102
 1.6% ( 50.0)               <kernel> :  SDC`sysdc_update
103
 0.2% (  8.0)               <kernel> :  cpudrv`cpudrv_monitor_disp
104
 0.2% (  7.6)               <kernel> :  ehci`ehci_handle_root_hub_status_change
105
 0.1% (  4.0)               <kernel> :  genunix`schedpaging
106
 0.1% (  2.0)            <interrupt> :  e1000g#0
107
 0.0% (  1.0)               <kernel> :  TS`ts_update
108
 0.0% (  1.0)               <kernel> :  e1000g`e1000g_local_timer
109
 0.0% (  1.0)            <interrupt> :  ehci#1
110
 0.0% (  0.8)            <interrupt> :  ehci#0
111
 0.0% (  0.2)               <kernel> :  genunix`kmem_update
112
 0.0% (  0.2)               <kernel> :  ahci`ahci_watchdog_handler
113
 0.0% (  0.2)               <kernel> :  genunix`vmem_update
114
 0.0% (  0.2)               <kernel> :  kcf`rnd_handler
115
 0.0% (  0.2)               <kernel> :  swrand`rnd_handler
116
 0.0% (  0.2)               <kernel> :  ibcm`ibcm_path_cache_timeout_cb
117

    
118
Suggestion: enable CPU power management by pressing the P key
119

    
120

    
121

    
122

    
123

    
124
root@lab10:~# prtdiag
125
System Configuration: Supermicro X9SCI/X9SCA
126
BIOS Configuration: American Megatrends Inc. 4.6.4 02/24/2011
127
BMC Configuration: IPMI 2.0 (KCS: Keyboard Controller Style)
128

    
129
==== Processor Sockets ====================================
130

    
131
Version                          Location Tag
132
-------------------------------- --------------------------
133
Intel(R) Xeon(R) CPU E31270 @ 3.40GHz SOCKET 0
134

    
135
==== Memory Device Sockets ================================
136

    
137
Type        Status Set Device Locator      Bank Locator
138
----------- ------ --- ------------------- ----------------
139
Unknown     in use 0   DIMM_1A             BANK0
140
Unknown     in use 0   DIMM_2A             BANK0
141
Unknown     in use 0   DIMM_1B             BANK0
142
Unknown     in use 0   DIMM_2B             BANK0
143

    
144
==== On-Board Devices =====================================
145
   To Be Filled By O.E.M.
146

    
147
==== Upgradeable Slots ====================================
148

    
149
ID  Status    Type             Description
150
--- --------- ---------------- ----------------------------
151
0   in use    PCI Express      J6B2
152
1   in use    PCI Express      J6B1
153
2   in use    PCI Express      J6D1
154
3   in use    PCI Express      J7B1
155
4   in use    PCI Express      J8B4
156
root@lab10:~#
157

    
158

    
159

    
160
root@lab10:~# cat /etc/power.conf
161
cpu_deep_idle enable
162
cpu-threshold 10s
163
cpupm disable
164

    
165

    
166

    
167

    
168
root@lab10:~# dtrace -n 'profile-10ms{@[stack()] = count()}'
169
dtrace: description 'profile-10ms' matched 1 probe
170
^C
171

    
172

    
173
              unix`av_check_softint_pending+0x50
174
              unix`av_dispatch_softvect+0x48
175
              apix`apix_dispatch_softint+0x34
176
              unix`switch_sp_and_call+0x13
177
                1
178

    
179
              unix`av_dispatch_softvect
180
              unix`switch_sp_and_call+0x13
181
                1
182

    
183
              unix`av_dispatch_softvect+0x1
184
              unix`switch_sp_and_call+0x13
185
                1
186

    
187
              genunix`lbolt_event_driven+0x18
188
              genunix`ddi_get_lbolt+0xd
189
              SDC`sysdc_update_times+0x50
190
              SDC`sysdc_compute_pri+0x4b
191
              SDC`sysdc_setrun+0x35
192
              SDC`sysdc_wakeup+0x15
193
              genunix`sleepq_wakeone_chan+0x89
194
              genunix`cv_signal+0x8e
195
              genunix`taskq_dispatch+0x374
196
              zfs`zio_taskq_dispatch+0xab
197
              zfs`zio_interrupt+0x1c
198
              zfs`vdev_disk_io_intr+0x6b
199
              genunix`biodone+0x84
200
              sd`sd_buf_iodone+0x67
201
              sd`sd_mapblockaddr_iodone+0x4f
202
              sd`sd_return_command+0x1d9
203
              sd`sdintr+0x58d
204
              scsi`scsi_hba_pkt_comp+0x15c
205
              sata`sata_txlt_rw_completion+0x1d3
206
              ahci`ahci_flush_doneq+0x6a
207
                1
208

    
209
              unix`0xfffffffffb85a6ca
210
              kstat`read_kstat_data+0x48d
211
              kstat`kstat_ioctl+0x4a
212
              genunix`cdev_ioctl+0x45
213
              specfs`spec_ioctl+0x5a
214
              genunix`fop_ioctl+0x7b
215
              genunix`ioctl+0x18e
216
              unix`_sys_sysenter_post_swapgs+0x149
217
                1
218

    
219
              genunix`cpu_update_pct+0x3e
220
              genunix`restore_mstate+0x40
221
              unix`swtch+0xfb
222
              unix`idle+0xc4
223
              unix`thread_start+0x8
224
                1
225

    
226
              unix`av_dispatch_softvect+0x2c
227
              apix`apix_dispatch_softint+0x34
228
              unix`switch_sp_and_call+0x13
229
                2
230

    
231
              unix`av_dispatch_softvect+0x41
232
              apix`apix_dispatch_softint+0x34
233
              unix`switch_sp_and_call+0x13
234
                2
235

    
236
                9
237

    
238
              apix`apix_dispatch_softint+0x27
239
              unix`switch_sp_and_call+0x13
240
               12
241

    
242
              unix`i86_mwait+0xd
243
              unix`cpu_idle_mwait+0xf1
244
              unix`cpu_acpi_idle+0x8d
245
              unix`cpu_idle_adaptive+0x19
246
              unix`idle+0x114
247
              unix`thread_start+0x8
248
               53
249

    
250
              unix`acpi_cpu_cstate+0x2ae
251
              unix`cpu_acpi_idle+0x82
252
              unix`cpu_idle_adaptive+0x19
253
              unix`idle+0x114
254
              unix`thread_start+0x8
255
            15340
256
root@lab10:~#
257

    
258

    
259

    
260

    
261

    
262
root@lab10:~# echo ::interrupts | mdb -k
263
CPU/Vect  IRQ IPL Bus    Trg Type   Share APIC/INT# ISR
264
0/0x25    16  9   PCI    Lvl Fixed  1     0x0/0x10  ehci_intr
265
1/0x20    9   9   PCI    Lvl Fixed  1     0x0/0x9   acpi_wrapper_isr
266
1/0x21    23  9   PCI    Lvl Fixed  1     0x0/0x17  ehci_intr
267
1/0x22    4   12  ISA    Edg Fixed  1     0x0/0x4   asyintr
268
2/0x20    11  14  PCI    Lvl Fixed  1     0x0/0xb   hpet_isr
269
2/0x21    -   6   PCI    Edg MSI    1     -         e1000g_intr_pciexpress
270
3/0x20    -   5   PCI    Edg MSI    1     -         ahci_intr
271
3/0x21    3   12  ISA    Edg Fixed  1     0x0/0x3   asyintr
272
5/0x20    10  12  ISA    Edg Fixed  1     0x0/0xa   asyintr
273
6/0x20    1   5   ISA    Edg Fixed  1     0x0/0x1   i8042_intr
274
6/0x21    -   6   PCI    Edg MSI    1     -         e1000g_intr_pciexpress
275
7/0x20    12  5   ISA    Edg Fixed  1     0x0/0xc   i8042_intr
276
all/0xf0  -   15  -      Edg IPI    1     -         xc_serv
277
all/0xf1  -   11  -      Edg IPI    0     -         poke_cpu
278
all/0xf2  -   14  -      Edg IPI    1     -         kcpc_hw_overflow_intr
279
all/0xf3  -   15  -      Edg IPI    1     -         apic_error_intr
280
all/0xf4  -   2   -      Edg IPI    1     -         cmi_cmci_trap
281
all/0xf5  -   14  -      Edg IPI    1     -         cbe_fire
282
all/0xf6  -   14  -      Edg IPI    1     -         cbe_fire
283
root@lab10:~#
284

    
285

    
286

    
287

    
288

    
289
root@lab10:~# echo ::interrupts -d | mdb -k
290
CPU/Vect  IRQ IPL Bus    Trg Type   Share APIC/INT# Driver Name(s)
291
0/0x25    16  9   PCI    Lvl Fixed  1     0x0/0x10  ehci#0
292
1/0x20    9   9   PCI    Lvl Fixed  1     0x0/0x9   acpi_wrapper_isr
293
1/0x21    23  9   PCI    Lvl Fixed  1     0x0/0x17  ehci#1
294
1/0x22    4   12  ISA    Edg Fixed  1     0x0/0x4   asy#0
295
2/0x20    11  14  PCI    Lvl Fixed  1     0x0/0xb   hpet_isr
296
2/0x21    -   6   PCI    Edg MSI    1     -         e1000g#0
297
3/0x20    -   5   PCI    Edg MSI    1     -         ahci#0
298
3/0x21    3   12  ISA    Edg Fixed  1     0x0/0x3   asy#1
299
5/0x20    10  12  ISA    Edg Fixed  1     0x0/0xa   asy#2
300
6/0x20    1   5   ISA    Edg Fixed  1     0x0/0x1   i8042#0
301
6/0x21    -   6   PCI    Edg MSI    1     -         e1000g#1
302
7/0x20    12  5   ISA    Edg Fixed  1     0x0/0xc   i8042#0
303
all/0xf0  -   15  -      Edg IPI    1     -         xc_serv
304
all/0xf1  -   11  -      Edg IPI    0     -         poke_cpu
305
all/0xf2  -   14  -      Edg IPI    1     -         kcpc_hw_overflow_intr
306
all/0xf3  -   15  -      Edg IPI    1     -         apic_error_intr
307
all/0xf4  -   2   -      Edg IPI    1     -         cmi_cmci_trap
308
all/0xf5  -   14  -      Edg IPI    1     -         cbe_fire
309
all/0xf6  -   14  -      Edg IPI    1     -         cbe_fire
310

    
311

    
312

    
313

    
314

    
315
root@lab10:~# intrstat 30
316

    
317
      device |      cpu0 %tim      cpu1 %tim      cpu2 %tim      cpu3 %tim      cpu4 %tim      cpu5 %tim      cpu6 %tim      cpu7 %tim
318
-------------+------------------------------------------------------------------------------------------------------------------------
319
      ahci#0 |         0  0.0         0  0.0         0  0.0         1  0.0         0  0.0         0  0.0         0  0.0         0  0.0
320
    e1000g#0 |         0  0.0         0  0.0         1  0.0         0  0.0         0  0.0         0  0.0         0  0.0         0  0.0
321
      ehci#0 |         0  0.0         0  0.0         0  0.0         0  0.0         0  0.0         0  0.0         0  0.0         0  0.0
322
      ehci#1 |         0  0.0         0  0.0         0  0.0         0  0.0         0  0.0         0  0.0         0  0.0         0  0.0
323
^C
324

    
325

    
326

    
327

    
328
root@lab10:~# powertop -t 30
329
OpenIndiana PowerTOP version 1.2   (C) 2009 Intel Corporation
330

    
331
Collecting data for 30.00 second(s)
332
root@lab10:~# vi /tmp/powertop.39
333
root@lab10:~# cat /tmp/powertop.39
334

    
335
                                                            OpenIndiana PowerTOP version 1.2
336

    
337
C-states (idle power)   Avg     Residency                                           P-states (frequencies)
338
C0 (cpu running)                (3.1%)                                              1600 Mhz        0.0%
339
C1                      0.0ms   (0.0%)                                              1800 Mhz        0.0%
340
C2                      0.0ms   (0.0%)                                              2000 Mhz        0.0%
341
C3                      2.4ms   (96.9%)                                             2200 Mhz        0.0%
342
                                                                                    2400 Mhz        0.0%
343
                                                                                    2600 Mhz        0.0%
344
                                                                                    2800 Mhz        0.0%
345
                                                                                    3000 Mhz        0.0%
346
                                                                                    3200 Mhz        0.0%
347
                                                                                    3400 Mhz        0.0%
348
                                                                                    3401 Mhz(turbo) 100.0%
349

    
350
Wakeups-from-idle per second: 3185.9    interval: 5.2s
351
no ACPI power usage estimate available
352

    
353
Top causes for wakeups:
354
89.3% (2845.4)                 sched :  <xcalls> unix`dtrace_xcall_func
355
 3.1% ( 99.9)               <kernel> :  genunix`clock
356
 2.4% ( 77.0)               <kernel> :  genunix`cv_wakeup
357
 1.6% ( 50.1)               <kernel> :  SDC`sysdc_update
358
 0.2% (  7.8)               <kernel> :  cpudrv`cpudrv_monitor_disp
359
 0.2% (  7.6)               <kernel> :  ehci`ehci_handle_root_hub_status_change
360
 0.1% (  4.0)               <kernel> :  genunix`schedpaging
361
 0.1% (  2.9)            <interrupt> :  e1000g#0
362
 0.0% (  1.1)            <interrupt> :  ehci#0
363
 0.0% (  1.0)               <kernel> :  TS`ts_update
364
 0.0% (  1.0)               <kernel> :  e1000g`e1000g_local_timer
365
 0.0% (  1.0)            <interrupt> :  ehci#1
366
 0.0% (  0.4)               <kernel> :  swrand`rnd_handler
367
 0.0% (  0.2)               <kernel> :  genunix`kmem_update
368
 0.0% (  0.2)               <kernel> :  genunix`vmem_update
369
 0.0% (  0.2)               <kernel> :  ip`tcp_timer_callback
370
 0.0% (  0.2)                  sched :  <xcalls> unix`hati_demap_func
371
 0.0% (  0.2)               <kernel> :  kcf`rnd_handler
372
 0.0% (  0.2)               <kernel> :  ip`igmp_slowtimo
373
 0.0% (  0.2)               <kernel> :  ahci`ahci_watchdog_handler
374

    
375

    
376

    
377
Suggestion: enable CPU power management by pressing the P key
378
                                                            OpenIndiana PowerTOP version 1.2
379

    
380
C-states (idle power)   Avg     Residency                                           P-states (frequencies)
381
C0 (cpu running)                (3.1%)                                              1600 Mhz        0.0%
382
C1                      0.0ms   (0.0%)                                              1800 Mhz        0.0%
383
C2                      0.0ms   (0.0%)                                              2000 Mhz        0.0%
384
C3                      2.4ms   (96.9%)                                             2200 Mhz        0.0%
385
                                                                                    2400 Mhz        0.0%
386
                                                                                    2600 Mhz        0.0%
387
                                                                                    2800 Mhz        0.0%
388
                                                                                    3000 Mhz        0.0%
389
                                                                                    3200 Mhz        0.0%
390
                                                                                    3400 Mhz        0.0%
391
                                                                                    3401 Mhz(turbo) 100.0%
392

    
393
Wakeups-from-idle per second: 3185.9    interval: 5.2s
394
no ACPI power usage estimate available
395

    
396
Top causes for wakeups:
397
89.3% (2845.4)                 sched :  <xcalls> unix`dtrace_xcall_func
398
 3.1% ( 99.9)               <kernel> :  genunix`clock
399
 2.4% ( 77.0)               <kernel> :  genunix`cv_wakeup
400
 1.6% ( 50.1)               <kernel> :  SDC`sysdc_update
401
 0.2% (  7.8)               <kernel> :  cpudrv`cpudrv_monitor_disp
402
 0.2% (  7.6)               <kernel> :  ehci`ehci_handle_root_hub_status_change
403
 0.1% (  4.0)               <kernel> :  genunix`schedpaging
404
 0.1% (  2.9)            <interrupt> :  e1000g#0
405
 0.0% (  1.1)            <interrupt> :  ehci#0
406
 0.0% (  1.0)               <kernel> :  TS`ts_update
407
 0.0% (  1.0)               <kernel> :  e1000g`e1000g_local_timer
408
 0.0% (  1.0)            <interrupt> :  ehci#1
409
 0.0% (  0.4)               <kernel> :  swrand`rnd_handler
410
 0.0% (  0.2)               <kernel> :  genunix`kmem_update
411
 0.0% (  0.2)               <kernel> :  genunix`vmem_update
412
 0.0% (  0.2)               <kernel> :  ip`tcp_timer_callback
413
 0.0% (  0.2)                  sched :  <xcalls> unix`hati_demap_func
414
 0.0% (  0.2)               <kernel> :  kcf`rnd_handler
415
 0.0% (  0.2)               <kernel> :  ip`igmp_slowtimo
416
 0.0% (  0.2)               <kernel> :  ahci`ahci_watchdog_handler
417

    
418

    
419

    
420
Suggestion: enable CPU power management by pressing the P key
421

    
422
root@lab10:~#
(2-2/18)