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/rand0aa5c1.cudf.difficult.log.runsolver ./aptitude-trendy-1.0 /home/misc2010/data/2010/difficult//rand0aa5c1.cudf /home/misc2010/tmp/201012070034/aptitude-trendy-1.0/rand0aa5c1.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.05 1.07 1.02 2/43 7275
/proc/meminfo: memFree=748016/1048576 swapFree=2077664/2097144
[pid=7275] ppid=7274 vsize=3028 CPUtime=0
/proc/7275/stat : 7275 (runsolver) D 7274 7275 4159 34819 4229 4202560 73 0 0 0 0 0 0 0 24 0 1 0 878222352 3100672 94 1283457024 134512640 134586868 4290737488 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0
/proc/7275/statm: 757 94 62 19 0 55 0

[startup+0.161112 s]
/proc/loadavg: 1.05 1.07 1.02 2/43 7275
/proc/meminfo: memFree=748016/1048576 swapFree=2077664/2097144
[pid=7275] ppid=7274 vsize=2584 CPUtime=0.02
/proc/7275/stat : 7275 (aptitude-trendy) S 7274 7275 4159 34819 4229 4202496 556 1858 0 0 0 0 0 2 25 0 1 0 878222352 2646016 282 1283457024 134512640 135304128 4289826112 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7275/statm: 646 282 240 194 0 32 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2584

[startup+0.206401 s]
/proc/loadavg: 1.05 1.07 1.02 2/43 7275
/proc/meminfo: memFree=748016/1048576 swapFree=2077664/2097144
[pid=7275] ppid=7274 vsize=2584 CPUtime=0.02
/proc/7275/stat : 7275 (aptitude-trendy) S 7274 7275 4159 34819 4229 4202496 556 1858 0 0 0 0 0 2 25 0 1 0 878222352 2646016 282 1283457024 134512640 135304128 4289826112 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7275/statm: 646 282 240 194 0 32 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2584

[startup+0.306423 s]
/proc/loadavg: 1.05 1.07 1.02 2/43 7275
/proc/meminfo: memFree=748016/1048576 swapFree=2077664/2097144
[pid=7275] ppid=7274 vsize=2584 CPUtime=0.02
/proc/7275/stat : 7275 (aptitude-trendy) S 7274 7275 4159 34819 4229 4202496 556 1858 0 0 0 0 0 2 25 0 1 0 878222352 2646016 282 1283457024 134512640 135304128 4289826112 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7275/statm: 646 282 240 194 0 32 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2584

[startup+0.706514 s]
/proc/loadavg: 1.05 1.07 1.02 2/43 7275
/proc/meminfo: memFree=748016/1048576 swapFree=2077664/2097144
[pid=7275] ppid=7274 vsize=2584 CPUtime=0.02
/proc/7275/stat : 7275 (aptitude-trendy) S 7274 7275 4159 34819 4229 4202496 556 1858 0 0 0 0 0 2 25 0 1 0 878222352 2646016 282 1283457024 134512640 135304128 4289826112 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7275/statm: 646 282 240 194 0 32 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2584

[startup+1.50669 s]
/proc/loadavg: 1.05 1.06 1.02 2/45 7286
/proc/meminfo: memFree=711832/1048576 swapFree=2077664/2097144
[pid=7275] ppid=7274 vsize=2584 CPUtime=0.02
/proc/7275/stat : 7275 (aptitude-trendy) S 7274 7275 4159 34819 4229 4202496 556 1858 0 0 0 0 0 2 25 0 1 0 878222352 2646016 282 1283457024 134512640 135304128 4289826112 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7275/statm: 646 282 240 194 0 32 0
[pid=7286] ppid=7275 vsize=33500 CPUtime=1.44
/proc/7286/stat : 7286 (cudftodeb.nativ) R 7275 7275 4159 34819 4229 4202496 7925 0 8 0 140 4 0 0 25 0 1 0 878222356 34304000 7860 1283457024 134512640 135004320 4292564800 18446744073709551615 134948159 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/7286/statm: 8375 7860 225 121 0 7767 0
Current children cumulated CPU time (s) 1.46
Current children cumulated vsize (KiB) 36084

[startup+3.10703 s]
/proc/loadavg: 1.05 1.06 1.02 2/45 7286
/proc/meminfo: memFree=689388/1048576 swapFree=2077664/2097144
[pid=7275] ppid=7274 vsize=2584 CPUtime=0.02
/proc/7275/stat : 7275 (aptitude-trendy) S 7274 7275 4159 34819 4229 4202496 556 1858 0 0 0 0 0 2 25 0 1 0 878222352 2646016 282 1283457024 134512640 135304128 4289826112 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7275/statm: 646 282 240 194 0 32 0
[pid=7286] ppid=7275 vsize=68360 CPUtime=3.03
/proc/7286/stat : 7286 (cudftodeb.nativ) R 7275 7275 4159 34819 4229 4202496 16509 0 8 0 296 7 0 0 25 0 1 0 878222356 70000640 16444 1283457024 134512640 135004320 4292564800 18446744073709551615 134950048 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/7286/statm: 17090 16444 237 121 0 16482 0
Current children cumulated CPU time (s) 3.05
Current children cumulated vsize (KiB) 70944

[startup+6.30552 s]
/proc/loadavg: 1.05 1.06 1.02 2/45 7286
/proc/meminfo: memFree=631356/1048576 swapFree=2077664/2097144
[pid=7275] ppid=7274 vsize=2592 CPUtime=5.54
/proc/7275/stat : 7275 (aptitude-trendy) S 7274 7275 4159 34819 4229 4202496 636 25889 0 8 0 0 537 17 18 0 1 0 878222352 2654208 285 1283457024 134512640 135304128 4289826112 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7275/statm: 648 285 241 194 0 34 0
Current children cumulated CPU time (s) 5.54
Current children cumulated vsize (KiB) 2592

[startup+12.7019 s]
/proc/loadavg: 1.04 1.06 1.02 3/46 7300
/proc/meminfo: memFree=634368/1048576 swapFree=2077664/2097144
[pid=7275] ppid=7274 vsize=2592 CPUtime=5.77
/proc/7275/stat : 7275 (aptitude-trendy) S 7274 7275 4159 34819 4229 4202496 679 28287 0 9 0 0 556 21 18 0 1 0 878222352 2654208 293 1283457024 134512640 135304128 4289826112 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7275/statm: 648 293 249 194 0 34 0
[pid=7296] ppid=7275 vsize=69280 CPUtime=4.41
/proc/7296/stat : 7296 (aptitude) R 7275 7275 4159 34819 4229 4202496 18436 650 340 0 436 5 0 0 25 0 2 0 878223012 70942720 11637 1283457024 134512640 137933492 4288921568 18446744073709551615 4159280661 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/7296/statm: 17320 11637 5758 836 0 9952 0
[pid=7296/tid=7298] ppid=7275 vsize=69280 CPUtime=1.05
/proc/7296/task/7298/stat : 7298 (aptitude) S 7275 7275 4159 34819 4229 4202560 3324 650 0 0 105 0 0 0 16 0 2 0 878223294 70942720 11637 1283457024 134512640 137933492 4288921568 18446744073709551615 4294960130 0 134217728 4096 0 18446612133086622720 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 10.18
Current children cumulated vsize (KiB) 71872

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

[startup+12.8085 s]
/proc/loadavg: 1.04 1.06 1.02 3/46 7300
/proc/meminfo: memFree=634368/1048576 swapFree=2077664/2097144
[pid=7275] ppid=7274 vsize=2592 CPUtime=5.77
/proc/7275/stat : 7275 (aptitude-trendy) S 7274 7275 4159 34819 4229 4202496 679 28287 0 9 0 0 556 21 18 0 1 0 878222352 2654208 293 1283457024 134512640 135304128 4289826112 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7275/statm: 648 293 249 194 0 34 0
[pid=7296] ppid=7275 vsize=69280 CPUtime=4.52
/proc/7296/stat : 7296 (aptitude) R 7275 7275 4159 34819 4229 4202496 19361 650 340 0 447 5 0 0 25 0 2 0 878223012 70942720 11637 1283457024 134512640 137933492 4288921568 18446744073709551615 135915188 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/7296/statm: 17320 11637 5758 836 0 9952 0
[pid=7296/tid=7298] ppid=7275 vsize=69280 CPUtime=1.05
/proc/7296/task/7298/stat : 7298 (aptitude) S 7275 7275 4159 34819 4229 4202560 3324 650 0 0 105 0 0 0 16 0 2 0 878223294 70942720 11637 1283457024 134512640 137933492 4288921568 18446744073709551615 4294960130 0 134217728 4096 0 18446612133086622720 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 10.29
Current children cumulated vsize (KiB) 71872

[startup+14.4078 s]
/proc/loadavg: 1.04 1.06 1.02 2/45 7302
/proc/meminfo: memFree=636632/1048576 swapFree=2077664/2097144
[pid=7275] ppid=7274 vsize=2592 CPUtime=11.03
/proc/7275/stat : 7275 (aptitude-trendy) S 7274 7275 4159 34819 4229 4202496 705 49304 0 349 0 0 1073 30 18 0 1 0 878222352 2654208 293 1283457024 134512640 135304128 4289826112 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7275/statm: 648 293 249 194 0 34 0
[pid=7302] ppid=7275 vsize=21064 CPUtime=0.81
/proc/7302/stat : 7302 (aptsolutions.na) R 7275 7275 4159 34819 4229 4202496 4859 0 9 0 78 3 0 0 24 0 1 0 878223707 21569536 4756 1283457024 134512640 134971616 4287440272 18446744073709551615 134800395 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/7302/statm: 5266 4756 204 113 0 4668 0
Current children cumulated CPU time (s) 11.84
Current children cumulated vsize (KiB) 23656

[startup+15.2081 s]
/proc/loadavg: 1.04 1.06 1.02 2/45 7302
/proc/meminfo: memFree=636632/1048576 swapFree=2077664/2097144
[pid=7275] ppid=7274 vsize=2592 CPUtime=11.03
/proc/7275/stat : 7275 (aptitude-trendy) S 7274 7275 4159 34819 4229 4202496 705 49304 0 349 0 0 1073 30 18 0 1 0 878222352 2654208 293 1283457024 134512640 135304128 4289826112 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7275/statm: 648 293 249 194 0 34 0
[pid=7302] ppid=7275 vsize=38056 CPUtime=1.61
/proc/7302/stat : 7302 (aptsolutions.na) R 7275 7275 4159 34819 4229 4202496 9040 0 9 0 154 7 0 0 25 0 1 0 878223707 38969344 8937 1283457024 134512640 134971616 4287440272 18446744073709551615 134919302 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/7302/statm: 9514 8937 204 113 0 8916 0
Current children cumulated CPU time (s) 12.64
Current children cumulated vsize (KiB) 40648

[startup+15.6082 s]
/proc/loadavg: 1.04 1.06 1.02 2/45 7302
/proc/meminfo: memFree=613072/1048576 swapFree=2077664/2097144
[pid=7275] ppid=7274 vsize=2592 CPUtime=11.03
/proc/7275/stat : 7275 (aptitude-trendy) S 7274 7275 4159 34819 4229 4202496 705 49304 0 349 0 0 1073 30 18 0 1 0 878222352 2654208 293 1283457024 134512640 135304128 4289826112 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7275/statm: 648 293 249 194 0 34 0
[pid=7302] ppid=7275 vsize=45992 CPUtime=2.01
/proc/7302/stat : 7302 (aptsolutions.na) R 7275 7275 4159 34819 4229 4202496 10969 0 9 0 194 7 0 0 25 0 1 0 878223707 47095808 10866 1283457024 134512640 134971616 4287440272 18446744073709551615 134915776 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/7302/statm: 11498 10866 204 113 0 10900 0
Current children cumulated CPU time (s) 13.04
Current children cumulated vsize (KiB) 48584

[startup+16.0084 s]
/proc/loadavg: 1.04 1.06 1.02 2/45 7302
/proc/meminfo: memFree=613072/1048576 swapFree=2077664/2097144
[pid=7275] ppid=7274 vsize=2592 CPUtime=11.03
/proc/7275/stat : 7275 (aptitude-trendy) S 7274 7275 4159 34819 4229 4202496 705 49304 0 349 0 0 1073 30 18 0 1 0 878222352 2654208 293 1283457024 134512640 135304128 4289826112 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/7275/statm: 648 293 249 194 0 34 0
[pid=7302] ppid=7275 vsize=57512 CPUtime=2.42
/proc/7302/stat : 7302 (aptsolutions.na) R 7275 7275 4159 34819 4229 4202496 13844 0 9 0 234 8 0 0 25 0 1 0 878223707 58892288 13741 1283457024 134512640 134971616 4287440272 18446744073709551615 134911431 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/7302/statm: 14378 13741 209 113 0 13780 0
Current children cumulated CPU time (s) 13.45
Current children cumulated vsize (KiB) 60104

Child status: 0
Real time (s): 16.0239
CPU time (s): 13.4688
CPU user time (s): 13.0768
CPU system time (s): 0.392024
CPU usage (%): 84.0549
Max. virtual memory (cumulated for all children) (KiB): 111004

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 13.0768
system time used= 0.392024
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 64199
page faults= 358
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 496
involuntary context switches= 374

runsolver used 0 second user time and 0 second system time

The end