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/randc10393.cudf.difficult.log.runsolver ./aptitude-trendy-1.0 /home/misc2010/data/2010/difficult//randc10393.cudf /home/misc2010/tmp/201012070034/aptitude-trendy-1.0/randc10393.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.02 1.06 1.01 2/41 4967
/proc/meminfo: memFree=685536/1048576 swapFree=2080288/2097144
[pid=4959] ppid=4958 vsize=2580 CPUtime=0
/proc/4959/stat : 4959 (aptitude-trendy) S 4958 4959 4159 34819 4229 4202496 516 1358 0 0 0 0 0 0 25 0 1 0 885324696 2641920 280 1283457024 134512640 135304128 4294609360 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/4959/statm: 645 280 237 194 0 31 0
[pid=4967] ppid=4959 vsize=2000 CPUtime=0.02
/proc/4967/stat : 4967 (cp) R 4959 4959 4159 34819 4229 4202496 253 0 0 0 0 2 0 0 25 0 1 0 885324697 2048000 182 1283457024 134512640 134614052 4288879840 18446744073709551615 4294960130 0 0 0 0 0 0 0 17 0 0 0 0
/proc/4967/statm: 500 182 145 25 0 46 0

[startup+0.150083 s]
/proc/loadavg: 1.02 1.06 1.01 2/41 4967
/proc/meminfo: memFree=685536/1048576 swapFree=2080288/2097144
[pid=4959] ppid=4958 vsize=2580 CPUtime=0.02
/proc/4959/stat : 4959 (aptitude-trendy) S 4958 4959 4159 34819 4229 4202496 565 1857 0 0 0 0 0 2 25 0 1 0 885324696 2641920 283 1283457024 134512640 135304128 4294609360 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/4959/statm: 645 283 240 194 0 31 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2580

[startup+0.210093 s]
/proc/loadavg: 1.02 1.06 1.01 2/41 4967
/proc/meminfo: memFree=685536/1048576 swapFree=2080288/2097144
[pid=4959] ppid=4958 vsize=2580 CPUtime=0.02
/proc/4959/stat : 4959 (aptitude-trendy) S 4958 4959 4159 34819 4229 4202496 565 1857 0 0 0 0 0 2 25 0 1 0 885324696 2641920 283 1283457024 134512640 135304128 4294609360 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/4959/statm: 645 283 240 194 0 31 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2580

[startup+0.310115 s]
/proc/loadavg: 1.02 1.06 1.01 2/41 4967
/proc/meminfo: memFree=685536/1048576 swapFree=2080288/2097144
[pid=4959] ppid=4958 vsize=2580 CPUtime=0.02
/proc/4959/stat : 4959 (aptitude-trendy) S 4958 4959 4159 34819 4229 4202496 565 1857 0 0 0 0 0 2 25 0 1 0 885324696 2641920 283 1283457024 134512640 135304128 4294609360 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/4959/statm: 645 283 240 194 0 31 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2580

[startup+0.710184 s]
/proc/loadavg: 1.02 1.06 1.01 2/41 4967
/proc/meminfo: memFree=685536/1048576 swapFree=2080288/2097144
[pid=4959] ppid=4958 vsize=2580 CPUtime=0.02
/proc/4959/stat : 4959 (aptitude-trendy) S 4958 4959 4159 34819 4229 4202496 565 1857 0 0 0 0 0 2 25 0 1 0 885324696 2641920 283 1283457024 134512640 135304128 4294609360 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/4959/statm: 645 283 240 194 0 31 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2580

[startup+1.51034 s]
/proc/loadavg: 1.02 1.06 1.01 2/42 4970
/proc/meminfo: memFree=660412/1048576 swapFree=2080288/2097144
[pid=4959] ppid=4958 vsize=2580 CPUtime=0.02
/proc/4959/stat : 4959 (aptitude-trendy) S 4958 4959 4159 34819 4229 4202496 565 1857 0 0 0 0 0 2 25 0 1 0 885324696 2641920 283 1283457024 134512640 135304128 4294609360 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/4959/statm: 645 283 240 194 0 31 0
[pid=4970] ppid=4959 vsize=33500 CPUtime=1.47
/proc/4970/stat : 4970 (cudftodeb.nativ) R 4959 4959 4159 34819 4229 4202496 7913 0 0 0 145 2 0 0 25 0 1 0 885324700 34304000 7840 1283457024 134512640 135004320 4294689328 18446744073709551615 134945052 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/4970/statm: 8375 7840 225 121 0 7767 0
Current children cumulated CPU time (s) 1.49
Current children cumulated vsize (KiB) 36080

[startup+3.11062 s]
/proc/loadavg: 1.02 1.05 1.01 2/42 4970
/proc/meminfo: memFree=638712/1048576 swapFree=2080288/2097144
[pid=4959] ppid=4958 vsize=2580 CPUtime=0.02
/proc/4959/stat : 4959 (aptitude-trendy) S 4958 4959 4159 34819 4229 4202496 565 1857 0 0 0 0 0 2 25 0 1 0 885324696 2641920 283 1283457024 134512640 135304128 4294609360 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/4959/statm: 645 283 240 194 0 31 0
[pid=4970] ppid=4959 vsize=67608 CPUtime=3.07
/proc/4970/stat : 4970 (cudftodeb.nativ) R 4959 4959 4159 34819 4229 4202496 16354 0 0 0 300 7 0 0 25 0 1 0 885324700 69230592 16281 1283457024 134512640 135004320 4294689328 18446744073709551615 134948148 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/4970/statm: 16902 16281 237 121 0 16294 0
Current children cumulated CPU time (s) 3.09
Current children cumulated vsize (KiB) 70188

[startup+6.30604 s]
/proc/loadavg: 1.02 1.05 1.01 2/42 4970
/proc/meminfo: memFree=580944/1048576 swapFree=2080288/2097144
[pid=4959] ppid=4958 vsize=2588 CPUtime=5.64
/proc/4959/stat : 4959 (aptitude-trendy) S 4958 4959 4159 34819 4229 4202496 649 25835 0 0 0 0 547 17 20 0 1 0 885324696 2650112 286 1283457024 134512640 135304128 4294609360 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/4959/statm: 647 286 241 194 0 33 0
Current children cumulated CPU time (s) 5.64
Current children cumulated vsize (KiB) 2588

[startup+12.7097 s]
/proc/loadavg: 1.09 1.07 1.02 2/43 4984
/proc/meminfo: memFree=597840/1048576 swapFree=2080288/2097144
[pid=4959] ppid=4958 vsize=2588 CPUtime=5.88
/proc/4959/stat : 4959 (aptitude-trendy) S 4958 4959 4159 34819 4229 4202496 693 28238 0 1 0 0 568 20 18 0 1 0 885324696 2650112 294 1283457024 134512640 135304128 4294609360 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/4959/statm: 647 294 249 194 0 33 0
[pid=4980] ppid=4959 vsize=64776 CPUtime=4.99
/proc/4980/stat : 4980 (aptitude) R 4959 4959 4159 34819 4229 4202496 17162 650 288 0 449 50 0 0 25 0 2 0 885325352 66330624 10723 1283457024 134512640 137933492 4290052320 18446744073709551615 4294960130 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/4980/statm: 16194 10723 5969 836 0 8825 0
[pid=4980/tid=4982] ppid=4959 vsize=64776 CPUtime=0.44
/proc/4980/task/4982/stat : 4982 (aptitude) R 4959 4959 4159 34819 4229 4202560 2299 650 1 0 43 1 0 0 16 0 2 0 885325589 66330624 10723 1283457024 134512640 137933492 4290052320 18446744073709551615 136261832 0 134217728 4096 0 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 10.87
Current children cumulated vsize (KiB) 67364

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

[startup+12.8024 s]
/proc/loadavg: 1.09 1.07 1.02 2/43 4984
/proc/meminfo: memFree=597840/1048576 swapFree=2080288/2097144
[pid=4959] ppid=4958 vsize=2588 CPUtime=5.88
/proc/4959/stat : 4959 (aptitude-trendy) S 4958 4959 4159 34819 4229 4202496 693 28238 0 1 0 0 568 20 18 0 1 0 885324696 2650112 294 1283457024 134512640 135304128 4294609360 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/4959/statm: 647 294 249 194 0 33 0
[pid=4980] ppid=4959 vsize=65172 CPUtime=5.08
/proc/4980/stat : 4980 (aptitude) R 4959 4959 4159 34819 4229 4202496 17749 650 289 0 458 50 0 0 25 0 2 0 885325352 66736128 10865 1283457024 134512640 137933492 4290052320 18446744073709551615 4153419256 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/4980/statm: 16293 10865 6005 836 0 8924 0
[pid=4980/tid=4982] ppid=4959 vsize=65172 CPUtime=0.47
/proc/4980/task/4982/stat : 4982 (aptitude) S 4959 4959 4159 34819 4229 4202560 2367 650 1 0 46 1 0 0 16 0 2 0 885325589 66736128 10865 1283457024 134512640 137933492 4290052320 18446744073709551615 4294960130 0 134217728 4096 0 18446612133393159168 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 10.96
Current children cumulated vsize (KiB) 67760

[startup+14.4107 s]
/proc/loadavg: 1.09 1.07 1.02 2/42 4986
/proc/meminfo: memFree=593456/1048576 swapFree=2080288/2097144
[pid=4959] ppid=4958 vsize=2588 CPUtime=11.68
/proc/4959/stat : 4959 (aptitude-trendy) S 4958 4959 4159 34819 4229 4202496 720 48419 0 290 0 0 1097 71 18 0 1 0 885324696 2650112 294 1283457024 134512640 135304128 4294609360 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/4959/statm: 647 294 249 194 0 33 0
[pid=4986] ppid=4959 vsize=21804 CPUtime=0.86
/proc/4986/stat : 4986 (aptsolutions.na) R 4959 4959 4159 34819 4229 4202496 5084 0 0 0 84 2 0 0 25 0 1 0 885326049 22327296 4972 1283457024 134512640 134971616 4293427424 18446744073709551615 134911423 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/4986/statm: 5451 4972 204 113 0 4853 0
Current children cumulated CPU time (s) 12.54
Current children cumulated vsize (KiB) 24392

[startup+15.2108 s]
/proc/loadavg: 1.09 1.07 1.02 2/42 4986
/proc/meminfo: memFree=593456/1048576 swapFree=2080288/2097144
[pid=4959] ppid=4958 vsize=2588 CPUtime=11.68
/proc/4959/stat : 4959 (aptitude-trendy) S 4958 4959 4159 34819 4229 4202496 720 48419 0 290 0 0 1097 71 18 0 1 0 885324696 2650112 294 1283457024 134512640 135304128 4294609360 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/4959/statm: 647 294 249 194 0 33 0
[pid=4986] ppid=4959 vsize=38548 CPUtime=1.66
/proc/4986/stat : 4986 (aptsolutions.na) R 4959 4959 4159 34819 4229 4202496 9197 0 0 0 163 3 0 0 25 0 1 0 885326049 39473152 9085 1283457024 134512640 134971616 4293427424 18446744073709551615 134927609 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/4986/statm: 9637 9085 204 113 0 9039 0
Current children cumulated CPU time (s) 13.34
Current children cumulated vsize (KiB) 41136

[startup+15.6109 s]
/proc/loadavg: 1.09 1.07 1.02 2/42 4986
/proc/meminfo: memFree=570268/1048576 swapFree=2080288/2097144
[pid=4959] ppid=4958 vsize=2588 CPUtime=11.68
/proc/4959/stat : 4959 (aptitude-trendy) S 4958 4959 4159 34819 4229 4202496 720 48419 0 290 0 0 1097 71 18 0 1 0 885324696 2650112 294 1283457024 134512640 135304128 4294609360 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/4959/statm: 647 294 249 194 0 33 0
[pid=4986] ppid=4959 vsize=46484 CPUtime=2.06
/proc/4986/stat : 4986 (aptsolutions.na) R 4959 4959 4159 34819 4229 4202496 11103 0 0 0 203 3 0 0 25 0 1 0 885326049 47599616 10991 1283457024 134512640 134971616 4293427424 18446744073709551615 134946602 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/4986/statm: 11621 10991 204 113 0 11023 0
Current children cumulated CPU time (s) 13.74
Current children cumulated vsize (KiB) 49072

[startup+15.811 s]
/proc/loadavg: 1.09 1.07 1.02 2/42 4986
/proc/meminfo: memFree=570268/1048576 swapFree=2080288/2097144
[pid=4959] ppid=4958 vsize=2588 CPUtime=11.68
/proc/4959/stat : 4959 (aptitude-trendy) S 4958 4959 4159 34819 4229 4202496 720 48419 0 290 0 0 1097 71 18 0 1 0 885324696 2650112 294 1283457024 134512640 135304128 4294609360 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/4959/statm: 647 294 249 194 0 33 0
[pid=4986] ppid=4959 vsize=50948 CPUtime=2.26
/proc/4986/stat : 4986 (aptsolutions.na) R 4959 4959 4159 34819 4229 4202496 12214 0 0 0 223 3 0 0 25 0 1 0 885326049 52170752 12102 1283457024 134512640 134971616 4293427424 18446744073709551615 4159309349 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/4986/statm: 12737 12102 204 113 0 12139 0
Current children cumulated CPU time (s) 13.94
Current children cumulated vsize (KiB) 53536

[startup+15.911 s]
/proc/loadavg: 1.09 1.07 1.02 2/42 4986
/proc/meminfo: memFree=570268/1048576 swapFree=2080288/2097144
[pid=4959] ppid=4958 vsize=2588 CPUtime=11.68
/proc/4959/stat : 4959 (aptitude-trendy) S 4958 4959 4159 34819 4229 4202496 720 48419 0 290 0 0 1097 71 18 0 1 0 885324696 2650112 294 1283457024 134512640 135304128 4294609360 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/4959/statm: 647 294 249 194 0 33 0
[pid=4986] ppid=4959 vsize=53804 CPUtime=2.36
/proc/4986/stat : 4986 (aptsolutions.na) R 4959 4959 4159 34819 4229 4202496 12978 0 0 0 233 3 0 0 25 0 1 0 885326049 55095296 12866 1283457024 134512640 134971616 4293427424 18446744073709551615 134964261 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/4986/statm: 13451 12866 208 113 0 12853 0
Current children cumulated CPU time (s) 14.04
Current children cumulated vsize (KiB) 56392

Child status: 0
Real time (s): 16.0085
CPU time (s): 14.1449
CPU user time (s): 13.3968
CPU system time (s): 0.748046
CPU usage (%): 88.3587
Max. virtual memory (cumulated for all children) (KiB): 110996

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 13.3968
system time used= 0.748046
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 63405
page faults= 290
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 344
involuntary context switches= 410

runsolver used 0 second user time and 0.004 second system time

The end