runsolver Copyright (C) 2010 Olivier ROUSSEL

This is runsolver version 3.2.9a (svn: 651)

This program is distributed in the hope that it will be useful,
but WITHOUT ANY WARRANTY; without even the implied warranty of
MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
GNU General Public License for more details.

command line: /home/misc2010/bin/runsolver -s SIGUSR1 -M 1124 -C 290 -d 10 -w /home/misc2010/tmp/201012070034/apt-pbo-trendy-1.0.6/rand655e63.cudf.impossible.log.runsolver ./apt-pbo-trendy-1.0.6 /home/misc2010/data/2010/impossible//rand655e63.cudf /home/misc2010/tmp/201012070034/apt-pbo-trendy-1.0.6/rand655e63.cudf.impossible.result 

Enforcing CPUTime limit (soft limit, will send signal-name then SIGKILL): 290 seconds
Enforcing CPUTime limit (hard limit, will send SIGXCPU): 320 seconds
Enforcing VSIZE limit (soft limit, will send signal-name then SIGKILL): 1150976 KiB
Enforcing VSIZE limit (hard limit, stack expansion will fail with SIGSEGV, brk() and mmap() will return ENOMEM): 1202176 KiB
Current StackSize limit: 8192 KiB


[startup+0 s]
/proc/loadavg: 1.01 1.07 1.03 1/40 14255
/proc/meminfo: memFree=952272/1048576 swapFree=2080252/2097144
[pid=14255] ppid=14254 vsize=3024 CPUtime=0
/proc/14255/stat : 14255 (runsolver) D 14254 14255 4159 34819 4229 4202560 73 0 0 0 0 0 0 0 21 0 1 0 879935960 3096576 94 1283457024 134512640 134586868 4291819088 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0
/proc/14255/statm: 756 94 62 19 0 54 0

[startup+0.155102 s]
/proc/loadavg: 1.01 1.07 1.03 1/40 14255
/proc/meminfo: memFree=952272/1048576 swapFree=2080252/2097144
[pid=14255] ppid=14254 vsize=1676 CPUtime=0
/proc/14255/stat : 14255 (sh) S 14254 14255 4159 34819 4229 4202496 221 174 0 0 0 0 0 0 22 0 1 0 879935960 1716224 128 1283457024 134512640 134594024 4290735648 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/14255/statm: 419 128 112 20 0 45 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 1676

[startup+0.207129 s]
/proc/loadavg: 1.01 1.07 1.03 1/40 14255
/proc/meminfo: memFree=952272/1048576 swapFree=2080252/2097144
[pid=14255] ppid=14254 vsize=1676 CPUtime=0
/proc/14255/stat : 14255 (sh) S 14254 14255 4159 34819 4229 4202496 221 174 0 0 0 0 0 0 22 0 1 0 879935960 1716224 128 1283457024 134512640 134594024 4290735648 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/14255/statm: 419 128 112 20 0 45 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 1676

[startup+0.307131 s]
/proc/loadavg: 1.01 1.07 1.03 1/40 14255
/proc/meminfo: memFree=952272/1048576 swapFree=2080252/2097144
[pid=14255] ppid=14254 vsize=1676 CPUtime=0
/proc/14255/stat : 14255 (sh) S 14254 14255 4159 34819 4229 4202496 221 174 0 0 0 0 0 0 22 0 1 0 879935960 1716224 128 1283457024 134512640 134594024 4290735648 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/14255/statm: 419 128 112 20 0 45 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 1676

[startup+0.714498 s]
/proc/loadavg: 1.01 1.07 1.03 1/40 14255
/proc/meminfo: memFree=952272/1048576 swapFree=2080252/2097144
[pid=14255] ppid=14254 vsize=1676 CPUtime=0
/proc/14255/stat : 14255 (sh) S 14254 14255 4159 34819 4229 4202496 221 174 0 0 0 0 0 0 22 0 1 0 879935960 1716224 128 1283457024 134512640 134594024 4290735648 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/14255/statm: 419 128 112 20 0 45 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 1676

[startup+1.50468 s]
/proc/loadavg: 1.01 1.07 1.03 2/43 14261
/proc/meminfo: memFree=928664/1048576 swapFree=2080252/2097144
[pid=14255] ppid=14254 vsize=1676 CPUtime=0
/proc/14255/stat : 14255 (sh) S 14254 14255 4159 34819 4229 4202496 221 174 0 0 0 0 0 0 22 0 1 0 879935960 1716224 128 1283457024 134512640 134594024 4290735648 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/14255/statm: 419 128 112 20 0 45 0
[pid=14258] ppid=14255 vsize=8356 CPUtime=0.02
/proc/14258/stat : 14258 (apt-pbo) S 14255 14255 4159 34819 4229 4202496 1583 413 29 0 2 0 0 0 23 0 1 0 879935961 8556544 1422 1283457024 134512640 135744540 4293255744 18446744073709551615 4294960130 0 0 128 0 18446744071564457842 0 0 17 0 0 0 0
/proc/14258/statm: 2089 1422 646 301 0 822 0
[pid=14261] ppid=14258 vsize=23620 CPUtime=0.96
/proc/14261/stat : 14261 (cudftodeb.nativ) R 14258 14255 4159 34819 4229 4202496 5538 0 11 0 94 2 0 0 25 0 1 0 879936004 24186880 5467 1283457024 134512640 135029684 4293857312 18446744073709551615 134825821 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/14261/statm: 5905 5467 247 127 0 5288 0
Current children cumulated CPU time (s) 0.98
Current children cumulated vsize (KiB) 33652

[startup+3.10508 s]
/proc/loadavg: 1.01 1.07 1.03 2/43 14261
/proc/meminfo: memFree=900036/1048576 swapFree=2080252/2097144
[pid=14255] ppid=14254 vsize=1676 CPUtime=0
/proc/14255/stat : 14255 (sh) S 14254 14255 4159 34819 4229 4202496 221 174 0 0 0 0 0 0 22 0 1 0 879935960 1716224 128 1283457024 134512640 134594024 4290735648 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/14255/statm: 419 128 112 20 0 45 0
[pid=14258] ppid=14255 vsize=8356 CPUtime=0.02
/proc/14258/stat : 14258 (apt-pbo) S 14255 14255 4159 34819 4229 4202496 1583 413 29 0 2 0 0 0 23 0 1 0 879935961 8556544 1422 1283457024 134512640 135744540 4293255744 18446744073709551615 4294960130 0 0 128 0 18446744071564457842 0 0 17 0 0 0 0
/proc/14258/statm: 2089 1422 646 301 0 822 0
[pid=14261] ppid=14258 vsize=56136 CPUtime=2.56
/proc/14261/stat : 14261 (cudftodeb.nativ) R 14258 14255 4159 34819 4229 4202496 13551 0 11 0 252 4 0 0 25 0 1 0 879936004 57483264 13480 1283457024 134512640 135029684 4293857312 18446744073709551615 134968855 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/14261/statm: 14034 13480 247 127 0 13417 0
Current children cumulated CPU time (s) 2.58
Current children cumulated vsize (KiB) 66168

[startup+6.31576 s]
/proc/loadavg: 1.01 1.07 1.02 2/43 14261
/proc/meminfo: memFree=822032/1048576 swapFree=2080252/2097144
[pid=14255] ppid=14254 vsize=1676 CPUtime=0
/proc/14255/stat : 14255 (sh) S 14254 14255 4159 34819 4229 4202496 221 174 0 0 0 0 0 0 22 0 1 0 879935960 1716224 128 1283457024 134512640 134594024 4290735648 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/14255/statm: 419 128 112 20 0 45 0
[pid=14258] ppid=14255 vsize=8356 CPUtime=0.02
/proc/14258/stat : 14258 (apt-pbo) S 14255 14255 4159 34819 4229 4202496 1583 413 29 0 2 0 0 0 23 0 1 0 879935961 8556544 1422 1283457024 134512640 135744540 4293255744 18446744073709551615 4294960130 0 0 128 0 18446744071564457842 0 0 17 0 0 0 0
/proc/14258/statm: 2089 1422 646 301 0 822 0
[pid=14261] ppid=14258 vsize=120904 CPUtime=5.76
/proc/14261/stat : 14261 (cudftodeb.nativ) R 14258 14255 4159 34819 4229 4202496 29651 0 11 0 561 15 0 0 25 0 1 0 879936004 123805696 29580 1283457024 134512640 135029684 4293857312 18446744073709551615 134968855 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/14261/statm: 30226 29580 257 127 0 29609 0
Current children cumulated CPU time (s) 5.78
Current children cumulated vsize (KiB) 130936

[startup+12.7102 s]
/proc/loadavg: 1.01 1.07 1.02 2/43 14261
/proc/meminfo: memFree=808664/1048576 swapFree=2080252/2097144
[pid=14255] ppid=14254 vsize=1676 CPUtime=0
/proc/14255/stat : 14255 (sh) S 14254 14255 4159 34819 4229 4202496 221 174 0 0 0 0 0 0 22 0 1 0 879935960 1716224 128 1283457024 134512640 134594024 4290735648 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/14255/statm: 419 128 112 20 0 45 0
[pid=14258] ppid=14255 vsize=8356 CPUtime=0.02
/proc/14258/stat : 14258 (apt-pbo) S 14255 14255 4159 34819 4229 4202496 1583 413 29 0 2 0 0 0 23 0 1 0 879935961 8556544 1422 1283457024 134512640 135744540 4293255744 18446744073709551615 4294960130 0 0 128 0 18446744071564457842 0 0 17 0 0 0 0
/proc/14258/statm: 2089 1422 646 301 0 822 0
[pid=14261] ppid=14258 vsize=99304 CPUtime=12.14
/proc/14261/stat : 14261 (cudftodeb.nativ) R 14258 14255 4159 34819 4229 4202496 38092 0 11 0 1057 157 0 0 25 0 1 0 879936004 101687296 24271 1283457024 134512640 135029684 4293857312 18446744073709551615 134865960 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/14261/statm: 24826 24271 258 127 0 24209 0
Current children cumulated CPU time (s) 12.16
Current children cumulated vsize (KiB) 109336

[startup+25.5056 s]
/proc/loadavg: 1.08 1.08 1.03 2/44 14274
/proc/meminfo: memFree=775188/1048576 swapFree=2080252/2097144
[pid=14255] ppid=14254 vsize=1676 CPUtime=0
/proc/14255/stat : 14255 (sh) S 14254 14255 4159 34819 4229 4202496 221 174 0 0 0 0 0 0 22 0 1 0 879935960 1716224 128 1283457024 134512640 134594024 4290735648 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/14255/statm: 419 128 112 20 0 45 0
[pid=14258] ppid=14255 vsize=48792 CPUtime=17.17
/proc/14258/stat : 14258 (apt-pbo) S 14255 14255 4159 34819 4229 4202496 11672 51353 29 571 57 46 1392 222 18 0 1 0 879935961 49963008 11082 1283457024 134512640 135744540 4293255744 18446744073709551615 4294960130 0 0 128 0 18446744071564457842 0 0 17 0 0 0 0
/proc/14258/statm: 12198 11082 9573 301 0 1535 0
[pid=14271] ppid=14258 vsize=2584 CPUtime=0
/proc/14271/stat : 14271 (apt-get.sh) S 14258 14255 4159 34819 4229 4202496 457 494 0 0 0 0 0 0 18 0 1 0 879937993 2646016 278 1283457024 134512640 135304128 4291148896 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/14271/statm: 646 278 235 194 0 32 0
[pid=14274] ppid=14271 vsize=45008 CPUtime=4.41
/proc/14274/stat : 14274 (apt-get) R 14271 14255 4159 34819 4229 4202496 10284 0 0 0 394 47 0 0 25 0 1 0 879937994 46088192 10161 1283457024 134512640 134649604 4294713312 18446744073709551615 4157420264 0 0 4096 134217728 0 0 0 17 0 0 0 0
/proc/14274/statm: 11252 10161 9272 34 0 946 0
Current children cumulated CPU time (s) 21.58
Current children cumulated vsize (KiB) 98060

Solver just ended. Dumping a history of the last processes samples

[startup+28.7063 s]
/proc/loadavg: 1.07 1.08 1.03 2/44 14274
/proc/meminfo: memFree=770476/1048576 swapFree=2080252/2097144
[pid=14255] ppid=14254 vsize=1676 CPUtime=0
/proc/14255/stat : 14255 (sh) S 14254 14255 4159 34819 4229 4202496 221 174 0 0 0 0 0 0 22 0 1 0 879935960 1716224 128 1283457024 134512640 134594024 4290735648 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/14255/statm: 419 128 112 20 0 45 0
[pid=14258] ppid=14255 vsize=48792 CPUtime=17.59
/proc/14258/stat : 14258 (apt-pbo) S 14255 14255 4159 34819 4229 4202496 11672 51353 29 571 73 72 1392 222 18 0 1 0 879935961 49963008 11082 1283457024 134512640 135744540 4293255744 18446744073709551615 4294960130 0 0 128 0 18446744071564457842 0 0 17 0 0 0 0
/proc/14258/statm: 12198 11082 9573 301 0 1535 0
[pid=14271] ppid=14258 vsize=2584 CPUtime=0
/proc/14271/stat : 14271 (apt-get.sh) S 14258 14255 4159 34819 4229 4202496 457 494 0 0 0 0 0 0 18 0 1 0 879937993 2646016 278 1283457024 134512640 135304128 4291148896 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/14271/statm: 646 278 235 194 0 32 0
[pid=14274] ppid=14271 vsize=45008 CPUtime=7.18
/proc/14274/stat : 14274 (apt-get) R 14271 14255 4159 34819 4229 4202496 10307 0 0 0 640 78 0 0 25 0 1 0 879937994 46088192 10184 1283457024 134512640 134649604 4294713312 18446744073709551615 4157392791 0 0 4096 134217728 0 0 0 17 0 0 0 0
/proc/14274/statm: 11252 10184 9272 34 0 946 0
Current children cumulated CPU time (s) 24.77
Current children cumulated vsize (KiB) 98060

[startup+31.9106 s]
/proc/loadavg: 1.07 1.08 1.03 2/44 14274
/proc/meminfo: memFree=766632/1048576 swapFree=2080252/2097144
[pid=14255] ppid=14254 vsize=1676 CPUtime=0
/proc/14255/stat : 14255 (sh) S 14254 14255 4159 34819 4229 4202496 221 174 0 0 0 0 0 0 22 0 1 0 879935960 1716224 128 1283457024 134512640 134594024 4290735648 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/14255/statm: 419 128 112 20 0 45 0
[pid=14258] ppid=14255 vsize=48792 CPUtime=18.06
/proc/14258/stat : 14258 (apt-pbo) S 14255 14255 4159 34819 4229 4202496 11672 51353 29 571 88 104 1392 222 18 0 1 0 879935961 49963008 11082 1283457024 134512640 135744540 4293255744 18446744073709551615 4294960130 0 0 128 0 18446744071564457842 0 0 17 0 0 0 0
/proc/14258/statm: 12198 11082 9573 301 0 1535 0
[pid=14271] ppid=14258 vsize=2584 CPUtime=0
/proc/14271/stat : 14271 (apt-get.sh) S 14258 14255 4159 34819 4229 4202496 457 494 0 0 0 0 0 0 18 0 1 0 879937993 2646016 278 1283457024 134512640 135304128 4291148896 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/14271/statm: 646 278 235 194 0 32 0
[pid=14274] ppid=14271 vsize=45264 CPUtime=9.83
/proc/14274/stat : 14274 (apt-get) R 14271 14255 4159 34819 4229 4202496 10392 0 0 0 873 110 0 0 25 0 1 0 879937994 46350336 10205 1283457024 134512640 134649604 4294713312 18446744073709551615 4157135426 0 0 4096 134217728 0 0 0 17 0 0 0 0
/proc/14274/statm: 11316 10205 9272 34 0 1010 0
Current children cumulated CPU time (s) 27.89
Current children cumulated vsize (KiB) 98316

[startup+32.7108 s]
/proc/loadavg: 1.07 1.08 1.03 2/44 14274
/proc/meminfo: memFree=766632/1048576 swapFree=2080252/2097144
[pid=14255] ppid=14254 vsize=1676 CPUtime=0
/proc/14255/stat : 14255 (sh) S 14254 14255 4159 34819 4229 4202496 221 174 0 0 0 0 0 0 22 0 1 0 879935960 1716224 128 1283457024 134512640 134594024 4290735648 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/14255/statm: 419 128 112 20 0 45 0
[pid=14258] ppid=14255 vsize=48792 CPUtime=18.18
/proc/14258/stat : 14258 (apt-pbo) S 14255 14255 4159 34819 4229 4202496 11672 51353 29 571 92 112 1392 222 18 0 1 0 879935961 49963008 11082 1283457024 134512640 135744540 4293255744 18446744073709551615 4294960130 0 0 128 0 18446744071564457842 0 0 17 0 0 0 0
/proc/14258/statm: 12198 11082 9573 301 0 1535 0
[pid=14271] ppid=14258 vsize=2584 CPUtime=0
/proc/14271/stat : 14271 (apt-get.sh) S 14258 14255 4159 34819 4229 4202496 457 494 0 0 0 0 0 0 18 0 1 0 879937993 2646016 278 1283457024 134512640 135304128 4291148896 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/14271/statm: 646 278 235 194 0 32 0
[pid=14274] ppid=14271 vsize=45264 CPUtime=10.51
/proc/14274/stat : 14274 (apt-get) R 14271 14255 4159 34819 4229 4202496 10398 0 0 0 930 121 0 0 25 0 1 0 879937994 46350336 10211 1283457024 134512640 134649604 4294713312 18446744073709551615 4157422547 0 0 4096 134217728 0 0 0 17 0 0 0 0
/proc/14274/statm: 11316 10211 9272 34 0 1010 0
Current children cumulated CPU time (s) 28.69
Current children cumulated vsize (KiB) 98316

[startup+33.5117 s]
/proc/loadavg: 1.07 1.08 1.03 2/44 14274
/proc/meminfo: memFree=762168/1048576 swapFree=2080252/2097144
[pid=14255] ppid=14254 vsize=1676 CPUtime=0
/proc/14255/stat : 14255 (sh) S 14254 14255 4159 34819 4229 4202496 221 174 0 0 0 0 0 0 22 0 1 0 879935960 1716224 128 1283457024 134512640 134594024 4290735648 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/14255/statm: 419 128 112 20 0 45 0
[pid=14258] ppid=14255 vsize=50844 CPUtime=29.26
/proc/14258/stat : 14258 (apt-pbo) S 14255 14255 4159 34819 4229 4202496 12303 62717 29 571 92 116 2344 374 18 0 1 0 879935961 52064256 11598 1283457024 134512640 135744540 4293255744 18446744073709551615 4294960130 0 0 128 0 18446744071564457842 0 0 17 0 0 0 0
/proc/14258/statm: 12711 11598 9576 301 0 2048 0
Current children cumulated CPU time (s) 29.26
Current children cumulated vsize (KiB) 52520

[startup+33.9128 s]
/proc/loadavg: 1.07 1.08 1.03 2/44 14274
/proc/meminfo: memFree=762168/1048576 swapFree=2080252/2097144
[pid=14255] ppid=14254 vsize=1676 CPUtime=0
/proc/14255/stat : 14255 (sh) S 14254 14255 4159 34819 4229 4202496 221 174 0 0 0 0 0 0 22 0 1 0 879935960 1716224 128 1283457024 134512640 134594024 4290735648 18446744073709551615 4294960130 0 0 0 2 18446744071564329979 0 0 17 0 0 0 0
/proc/14255/statm: 419 128 112 20 0 45 0
[pid=14258] ppid=14255 vsize=48708 CPUtime=29.34
/proc/14258/stat : 14258 (apt-pbo) R 14255 14255 4159 34819 4229 4202496 12661 62717 29 571 96 120 2344 374 18 0 1 0 879935961 49876992 4924 1283457024 134512640 135744540 4293255744 18446744073709551615 4294960130 0 0 128 0 0 0 0 17 0 0 0 0
/proc/14258/statm: 12177 4924 3434 301 0 1514 0
Current children cumulated CPU time (s) 29.34
Current children cumulated vsize (KiB) 50384

Child status: 0
Real time (s): 33.9175
CPU time (s): 29.3618
CPU user time (s): 24.4175
CPU system time (s): 4.94431
CPU usage (%): 86.5684
Max. virtual memory (cumulated for all children) (KiB): 161176

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 24.4175
system time used= 4.94431
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 75913
page faults= 600
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 271576
involuntary context switches= 271636

runsolver used 0.004 second user time and 0 second system time

The end