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/aptitude-trendy-1.0/rand7b4167.cudf.difficult.log.runsolver ./aptitude-trendy-1.0 /home/misc2010/data/2010/difficult//rand7b4167.cudf /home/misc2010/tmp/201012070034/aptitude-trendy-1.0/rand7b4167.cudf.difficult.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.04 1.06 1.01 3/45 29259
/proc/meminfo: memFree=653996/1048576 swapFree=2077628/2097144
[pid=29251] ppid=29250 vsize=2580 CPUtime=0
/proc/29251/stat : 29251 (aptitude-trendy) S 29250 29251 4159 34819 4229 4202496 516 1356 0 0 0 0 0 0 25 0 1 0 883636154 2641920 279 1283457024 134512640 135304128 4294111568 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/29251/statm: 645 279 237 194 0 31 0
[pid=29259] ppid=29251 vsize=2000 CPUtime=0.03
/proc/29259/stat : 29259 (cp) R 29251 29251 4159 34819 4229 4202496 253 0 0 0 0 3 0 0 25 0 1 0 883636155 2048000 182 1283457024 134512640 134614052 4292968656 18446744073709551615 4294960130 0 0 0 0 0 0 0 17 0 0 0 0
/proc/29259/statm: 500 182 145 25 0 46 0

[startup+0.160952 s]
/proc/loadavg: 1.04 1.06 1.01 3/45 29259
/proc/meminfo: memFree=653996/1048576 swapFree=2077628/2097144
[pid=29251] ppid=29250 vsize=2580 CPUtime=0.03
/proc/29251/stat : 29251 (aptitude-trendy) S 29250 29251 4159 34819 4229 4202496 565 1855 0 0 0 0 0 3 25 0 1 0 883636154 2641920 282 1283457024 134512640 135304128 4294111568 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/29251/statm: 645 282 240 194 0 31 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 2580

[startup+0.208636 s]
/proc/loadavg: 1.04 1.06 1.01 3/45 29259
/proc/meminfo: memFree=653996/1048576 swapFree=2077628/2097144
[pid=29251] ppid=29250 vsize=2580 CPUtime=0.03
/proc/29251/stat : 29251 (aptitude-trendy) S 29250 29251 4159 34819 4229 4202496 565 1855 0 0 0 0 0 3 25 0 1 0 883636154 2641920 282 1283457024 134512640 135304128 4294111568 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/29251/statm: 645 282 240 194 0 31 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 2580

[startup+0.308656 s]
/proc/loadavg: 1.04 1.06 1.01 3/45 29259
/proc/meminfo: memFree=653996/1048576 swapFree=2077628/2097144
[pid=29251] ppid=29250 vsize=2580 CPUtime=0.03
/proc/29251/stat : 29251 (aptitude-trendy) S 29250 29251 4159 34819 4229 4202496 565 1855 0 0 0 0 0 3 25 0 1 0 883636154 2641920 282 1283457024 134512640 135304128 4294111568 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/29251/statm: 645 282 240 194 0 31 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 2580

[startup+0.70873 s]
/proc/loadavg: 1.04 1.06 1.01 3/45 29259
/proc/meminfo: memFree=653996/1048576 swapFree=2077628/2097144
[pid=29251] ppid=29250 vsize=2580 CPUtime=0.03
/proc/29251/stat : 29251 (aptitude-trendy) S 29250 29251 4159 34819 4229 4202496 565 1855 0 0 0 0 0 3 25 0 1 0 883636154 2641920 282 1283457024 134512640 135304128 4294111568 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/29251/statm: 645 282 240 194 0 31 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 2580

[startup+1.50891 s]
/proc/loadavg: 1.03 1.06 1.01 2/46 29262
/proc/meminfo: memFree=628004/1048576 swapFree=2077628/2097144
[pid=29251] ppid=29250 vsize=2580 CPUtime=0.03
/proc/29251/stat : 29251 (aptitude-trendy) S 29250 29251 4159 34819 4229 4202496 565 1855 0 0 0 0 0 3 25 0 1 0 883636154 2641920 282 1283457024 134512640 135304128 4294111568 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/29251/statm: 645 282 240 194 0 31 0
[pid=29262] ppid=29251 vsize=33748 CPUtime=1.46
/proc/29262/stat : 29262 (cudftodeb.nativ) R 29251 29251 4159 34819 4229 4202496 8011 0 0 0 142 4 0 0 25 0 1 0 883636158 34557952 7938 1283457024 134512640 135004320 4292323312 18446744073709551615 134953036 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/29262/statm: 8437 7938 225 121 0 7829 0
Current children cumulated CPU time (s) 1.49
Current children cumulated vsize (KiB) 36328

[startup+3.10928 s]
/proc/loadavg: 1.03 1.06 1.01 2/46 29262
/proc/meminfo: memFree=605808/1048576 swapFree=2077628/2097144
[pid=29251] ppid=29250 vsize=2580 CPUtime=0.03
/proc/29251/stat : 29251 (aptitude-trendy) S 29250 29251 4159 34819 4229 4202496 565 1855 0 0 0 0 0 3 25 0 1 0 883636154 2641920 282 1283457024 134512640 135304128 4294111568 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/29251/statm: 645 282 240 194 0 31 0
[pid=29262] ppid=29251 vsize=68856 CPUtime=3.06
/proc/29262/stat : 29262 (cudftodeb.nativ) R 29251 29251 4159 34819 4229 4202496 16647 0 0 0 301 5 0 0 25 0 1 0 883636158 70508544 16574 1283457024 134512640 135004320 4292323312 18446744073709551615 134943783 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/29262/statm: 17214 16574 237 121 0 16606 0
Current children cumulated CPU time (s) 3.09
Current children cumulated vsize (KiB) 71436

[startup+6.30641 s]
/proc/loadavg: 1.03 1.06 1.01 2/46 29262
/proc/meminfo: memFree=594772/1048576 swapFree=2077628/2097144
[pid=29251] ppid=29250 vsize=2588 CPUtime=5.54
/proc/29251/stat : 29251 (aptitude-trendy) S 29250 29251 4159 34819 4229 4202496 646 25955 0 0 0 0 537 17 20 0 1 0 883636154 2650112 285 1283457024 134512640 135304128 4294111568 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/29251/statm: 647 285 241 194 0 33 0
Current children cumulated CPU time (s) 5.54
Current children cumulated vsize (KiB) 2588

[startup+12.7041 s]
/proc/loadavg: 1.03 1.06 1.01 2/47 29275
/proc/meminfo: memFree=566136/1048576 swapFree=2077628/2097144
[pid=29251] ppid=29250 vsize=2588 CPUtime=5.78
/proc/29251/stat : 29251 (aptitude-trendy) S 29250 29251 4159 34819 4229 4202496 690 28351 0 1 0 0 558 20 18 0 1 0 883636154 2650112 293 1283457024 134512640 135304128 4294111568 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/29251/statm: 647 293 249 194 0 33 0
[pid=29272] ppid=29251 vsize=58300 CPUtime=5.38
/proc/29272/stat : 29272 (aptitude) R 29251 29251 4159 34819 4229 4202496 14864 650 266 0 460 78 0 0 25 0 2 0 883636796 59699200 9020 1283457024 134512640 137933492 4290740688 18446744073709551615 4153437264 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/29272/statm: 14575 9020 5913 836 0 7207 0
[pid=29272/tid=29274] ppid=29251 vsize=58300 CPUtime=0
/proc/29272/task/29274/stat : 29274 (aptitude) S 29251 29251 4159 34819 4229 4202560 5 650 0 0 0 0 0 0 15 0 2 0 883637015 59699200 9020 1283457024 134512640 137933492 4290740688 18446744073709551615 4294960130 0 134217728 4096 0 18446612133055116608 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 11.16
Current children cumulated vsize (KiB) 60888

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

[startup+12.8041 s]
/proc/loadavg: 1.03 1.06 1.01 2/47 29275
/proc/meminfo: memFree=566136/1048576 swapFree=2077628/2097144
[pid=29251] ppid=29250 vsize=2588 CPUtime=5.78
/proc/29251/stat : 29251 (aptitude-trendy) S 29250 29251 4159 34819 4229 4202496 690 28351 0 1 0 0 558 20 18 0 1 0 883636154 2650112 293 1283457024 134512640 135304128 4294111568 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/29251/statm: 647 293 249 194 0 33 0
[pid=29272] ppid=29251 vsize=58300 CPUtime=5.48
/proc/29272/stat : 29272 (aptitude) R 29251 29251 4159 34819 4229 4202496 14865 650 266 0 470 78 0 0 25 0 2 0 883636796 59699200 9021 1283457024 134512640 137933492 4290740688 18446744073709551615 4159468611 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/29272/statm: 14575 9021 5913 836 0 7207 0
[pid=29272/tid=29274] ppid=29251 vsize=58300 CPUtime=0
/proc/29272/task/29274/stat : 29274 (aptitude) S 29251 29251 4159 34819 4229 4202560 5 650 0 0 0 0 0 0 15 0 2 0 883637015 59699200 9021 1283457024 134512640 137933492 4290740688 18446744073709551615 4294960130 0 134217728 4096 0 18446612133055116608 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 11.26
Current children cumulated vsize (KiB) 60888

[startup+16.0049 s]
/proc/loadavg: 1.03 1.06 1.01 3/47 29276
/proc/meminfo: memFree=554604/1048576 swapFree=2077628/2097144
[pid=29251] ppid=29250 vsize=2588 CPUtime=5.78
/proc/29251/stat : 29251 (aptitude-trendy) S 29250 29251 4159 34819 4229 4202496 690 28351 0 1 0 0 558 20 18 0 1 0 883636154 2650112 293 1283457024 134512640 135304128 4294111568 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/29251/statm: 647 293 249 194 0 33 0
[pid=29272] ppid=29251 vsize=71764 CPUtime=8.67
/proc/29272/stat : 29272 (aptitude) R 29251 29251 4159 34819 4229 4202496 18909 650 266 0 787 80 0 0 20 0 2 0 883636796 73486336 12466 1283457024 134512640 137933492 4290740688 18446744073709551615 4294960130 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/29272/statm: 17941 12466 5969 836 0 10573 0
[pid=29272/tid=29274] ppid=29251 vsize=71764 CPUtime=2.88
/proc/29272/task/29274/stat : 29274 (aptitude) R 29251 29251 4159 34819 4229 4202560 4042 650 0 0 286 2 0 0 19 0 2 0 883637015 73486336 12466 1283457024 134512640 137933492 4290740688 18446744073709551615 135235968 0 134217728 4096 0 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 14.45
Current children cumulated vsize (KiB) 74352

[startup+17.6053 s]
/proc/loadavg: 1.02 1.05 1.01 2/46 29278
/proc/meminfo: memFree=569492/1048576 swapFree=2077628/2097144
[pid=29251] ppid=29250 vsize=2588 CPUtime=15.64
/proc/29251/stat : 29251 (aptitude-trendy) S 29250 29251 4159 34819 4229 4202496 717 50361 0 267 0 0 1459 105 18 0 1 0 883636154 2650112 293 1283457024 134512640 135304128 4294111568 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/29251/statm: 647 293 249 194 0 33 0
[pid=29278] ppid=29251 vsize=11816 CPUtime=0.41
/proc/29278/stat : 29278 (aptsolutions.na) R 29251 29251 4159 34819 4229 4202496 2601 0 0 0 41 0 0 0 20 0 1 0 883637874 12099584 2489 1283457024 134512640 134971616 4292821072 18446744073709551615 134954147 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/29278/statm: 2954 2489 204 113 0 2356 0
Current children cumulated CPU time (s) 16.05
Current children cumulated vsize (KiB) 14404

[startup+18.4055 s]
/proc/loadavg: 1.02 1.05 1.01 2/46 29278
/proc/meminfo: memFree=569492/1048576 swapFree=2077628/2097144
[pid=29251] ppid=29250 vsize=2588 CPUtime=15.64
/proc/29251/stat : 29251 (aptitude-trendy) S 29250 29251 4159 34819 4229 4202496 717 50361 0 267 0 0 1459 105 18 0 1 0 883636154 2650112 293 1283457024 134512640 135304128 4294111568 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/29251/statm: 647 293 249 194 0 33 0
[pid=29278] ppid=29251 vsize=28748 CPUtime=1.2
/proc/29278/stat : 29278 (aptsolutions.na) R 29251 29251 4159 34819 4229 4202496 6803 0 0 0 120 0 0 0 22 0 1 0 883637874 29437952 6691 1283457024 134512640 134971616 4292821072 18446744073709551615 134953918 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/29278/statm: 7187 6691 204 113 0 6589 0
Current children cumulated CPU time (s) 16.84
Current children cumulated vsize (KiB) 31336

[startup+19.2057 s]
/proc/loadavg: 1.02 1.05 1.01 2/46 29278
/proc/meminfo: memFree=546800/1048576 swapFree=2077628/2097144
[pid=29251] ppid=29250 vsize=2588 CPUtime=15.64
/proc/29251/stat : 29251 (aptitude-trendy) S 29250 29251 4159 34819 4229 4202496 717 50361 0 267 0 0 1459 105 18 0 1 0 883636154 2650112 293 1283457024 134512640 135304128 4294111568 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/29251/statm: 647 293 249 194 0 33 0
[pid=29278] ppid=29251 vsize=44748 CPUtime=2
/proc/29278/stat : 29278 (aptsolutions.na) R 29251 29251 4159 34819 4229 4202496 10731 0 0 0 198 2 0 0 25 0 1 0 883637874 45821952 10619 1283457024 134512640 134971616 4292821072 18446744073709551615 134912812 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/29278/statm: 11187 10619 204 113 0 10589 0
Current children cumulated CPU time (s) 17.64
Current children cumulated vsize (KiB) 47336

[startup+19.6057 s]
/proc/loadavg: 1.02 1.05 1.01 2/46 29278
/proc/meminfo: memFree=546800/1048576 swapFree=2077628/2097144
[pid=29251] ppid=29250 vsize=2588 CPUtime=15.64
/proc/29251/stat : 29251 (aptitude-trendy) S 29250 29251 4159 34819 4229 4202496 717 50361 0 267 0 0 1459 105 18 0 1 0 883636154 2650112 293 1283457024 134512640 135304128 4294111568 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/29251/statm: 647 293 249 194 0 33 0
[pid=29278] ppid=29251 vsize=54796 CPUtime=2.4
/proc/29278/stat : 29278 (aptsolutions.na) R 29251 29251 4159 34819 4229 4202496 13194 0 0 0 238 2 0 0 25 0 1 0 883637874 56111104 13082 1283457024 134512640 134971616 4292821072 18446744073709551615 134911397 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/29278/statm: 13699 13082 208 113 0 13101 0
Current children cumulated CPU time (s) 18.04
Current children cumulated vsize (KiB) 57384

Child status: 0
Real time (s): 19.6767
CPU time (s): 18.1251
CPU user time (s): 17.0291
CPU system time (s): 1.09607
CPU usage (%): 92.1145
Max. virtual memory (cumulated for all children) (KiB): 111000

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 17.0291
system time used= 1.09607
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 65277
page faults= 267
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 272
involuntary context switches= 440

runsolver used 0 second user time and 0 second system time

The end