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/201012091434/cudf2pbo4user-1.0/rande4fcd8.cudf.difficult.log.runsolver ./cudf2pbo4user-1.0 /home/misc2010/data/2010/difficult//rande4fcd8.cudf /home/misc2010/tmp/201012091434/cudf2pbo4user-1.0/rande4fcd8.cudf.difficult.result -changed,-removed,-unmet_recommends,-new 

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.19 1.18 1.09 3/38 1396
/proc/meminfo: memFree=317628/1048576 swapFree=2095372/2097144
[pid=1395] ppid=1394 vsize=2568 CPUtime=0
/proc/1395/stat : 1395 (cudf2pbo4user-1) S 1394 1395 25521 34816 25544 4202496 383 0 0 0 0 0 0 0 18 0 1 0 900596122 2629632 279 1283457024 134512640 135304128 4294615440 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/1395/statm: 642 279 240 194 0 28 0
[pid=1396] ppid=1395 vsize=2568 CPUtime=0
/proc/1396/stat : 1396 (cudf2pbo4user-1) D 1395 1395 25521 34816 25544 4202560 79 0 0 0 0 0 0 0 18 0 1 0 900596122 2629632 102 1283457024 134512640 135304128 4294615440 18446744073709551615 4294960130 0 0 0 0 18446744071564252162 0 0 17 0 0 0 0
/proc/1396/statm: 642 102 62 194 0 28 0

[startup+0.137742 s]
/proc/loadavg: 1.19 1.18 1.09 3/38 1396
/proc/meminfo: memFree=317628/1048576 swapFree=2095372/2097144
[pid=1395] ppid=1394 vsize=2568 CPUtime=0
/proc/1395/stat : 1395 (cudf2pbo4user-1) S 1394 1395 25521 34816 25544 4202496 383 0 0 0 0 0 0 0 18 0 1 0 900596122 2629632 279 1283457024 134512640 135304128 4294615440 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/1395/statm: 642 279 240 194 0 28 0
[pid=1396] ppid=1395 vsize=7332 CPUtime=0.12
/proc/1396/stat : 1396 (cudf_msu32) R 1395 1395 25521 34816 25544 4202496 1633 0 0 0 12 0 0 0 25 0 1 0 900596122 7507968 1526 1283457024 134512640 136125367 4292630576 18446744073709551615 134717794 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/1396/statm: 1833 1526 146 394 0 1437 0
Current children cumulated CPU time (s) 0.12
Current children cumulated vsize (KiB) 9900

[startup+0.207753 s]
/proc/loadavg: 1.19 1.18 1.09 3/38 1396
/proc/meminfo: memFree=317628/1048576 swapFree=2095372/2097144
[pid=1395] ppid=1394 vsize=2568 CPUtime=0
/proc/1395/stat : 1395 (cudf2pbo4user-1) S 1394 1395 25521 34816 25544 4202496 383 0 0 0 0 0 0 0 18 0 1 0 900596122 2629632 279 1283457024 134512640 135304128 4294615440 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/1395/statm: 642 279 240 194 0 28 0
[pid=1396] ppid=1395 vsize=9984 CPUtime=0.18
/proc/1396/stat : 1396 (cudf_msu32) R 1395 1395 25521 34816 25544 4202496 2323 0 0 0 18 0 0 0 25 0 1 0 900596122 10223616 2216 1283457024 134512640 136125367 4292630576 18446744073709551615 134717794 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/1396/statm: 2496 2216 146 394 0 2100 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 12552

[startup+0.307772 s]
/proc/loadavg: 1.19 1.18 1.09 3/38 1396
/proc/meminfo: memFree=317628/1048576 swapFree=2095372/2097144
[pid=1395] ppid=1394 vsize=2568 CPUtime=0
/proc/1395/stat : 1395 (cudf2pbo4user-1) S 1394 1395 25521 34816 25544 4202496 383 0 0 0 0 0 0 0 18 0 1 0 900596122 2629632 279 1283457024 134512640 135304128 4294615440 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/1395/statm: 642 279 240 194 0 28 0
[pid=1396] ppid=1395 vsize=13744 CPUtime=0.28
/proc/1396/stat : 1396 (cudf_msu32) R 1395 1395 25521 34816 25544 4202496 3234 0 0 0 27 1 0 0 25 0 1 0 900596122 14073856 3127 1283457024 134512640 136125367 4292630576 18446744073709551615 134738215 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/1396/statm: 3436 3127 147 394 0 3040 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 16312

[startup+0.707893 s]
/proc/loadavg: 1.19 1.18 1.09 3/38 1396
/proc/meminfo: memFree=317628/1048576 swapFree=2095372/2097144
[pid=1395] ppid=1394 vsize=2568 CPUtime=0
/proc/1395/stat : 1395 (cudf2pbo4user-1) S 1394 1395 25521 34816 25544 4202496 383 0 0 0 0 0 0 0 18 0 1 0 900596122 2629632 279 1283457024 134512640 135304128 4294615440 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/1395/statm: 642 279 240 194 0 28 0
[pid=1396] ppid=1395 vsize=25952 CPUtime=0.68
/proc/1396/stat : 1396 (cudf_msu32) R 1395 1395 25521 34816 25544 4202496 6300 0 0 0 66 2 0 0 25 0 1 0 900596122 26574848 6193 1283457024 134512640 136125367 4292630576 18446744073709551615 134717925 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/1396/statm: 6488 6193 147 394 0 6092 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 28520

[startup+1.50949 s]
/proc/loadavg: 1.19 1.18 1.09 2/39 1397
/proc/meminfo: memFree=282640/1048576 swapFree=2095372/2097144
[pid=1395] ppid=1394 vsize=2568 CPUtime=1.25
/proc/1395/stat : 1395 (cudf2pbo4user-1) S 1394 1395 25521 34816 25544 4202496 401 8842 0 0 0 0 107 18 20 0 1 0 900596122 2629632 280 1283457024 134512640 135304128 4294615440 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/1395/statm: 642 280 241 194 0 28 0
Current children cumulated CPU time (s) 1.25
Current children cumulated vsize (KiB) 2568

[startup+3.11003 s]
/proc/loadavg: 1.18 1.18 1.09 2/39 1398
/proc/meminfo: memFree=302108/1048576 swapFree=2095372/2097144
[pid=1395] ppid=1394 vsize=2568 CPUtime=1.25
/proc/1395/stat : 1395 (cudf2pbo4user-1) S 1394 1395 25521 34816 25544 4202496 401 8842 0 0 0 0 107 18 20 0 1 0 900596122 2629632 280 1283457024 134512640 135304128 4294615440 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/1395/statm: 642 280 241 194 0 28 0
[pid=1398] ppid=1395 vsize=15884 CPUtime=1.8
/proc/1398/stat : 1398 (bmo-pblex32) R 1395 1395 25521 34816 25544 4202496 4413 0 0 0 136 44 0 0 25 0 1 0 900596250 16265216 3693 1283457024 134512640 135887319 4286792384 18446744073709551615 134614953 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/1398/statm: 3971 3693 138 336 0 3633 0
Current children cumulated CPU time (s) 3.05
Current children cumulated vsize (KiB) 18452

[startup+6.31101 s]
/proc/loadavg: 1.18 1.18 1.09 2/39 1398
/proc/meminfo: memFree=299628/1048576 swapFree=2095372/2097144
[pid=1395] ppid=1394 vsize=2568 CPUtime=1.25
/proc/1395/stat : 1395 (cudf2pbo4user-1) S 1394 1395 25521 34816 25544 4202496 401 8842 0 0 0 0 107 18 20 0 1 0 900596122 2629632 280 1283457024 134512640 135304128 4294615440 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/1395/statm: 642 280 241 194 0 28 0
[pid=1398] ppid=1395 vsize=18168 CPUtime=4.99
/proc/1398/stat : 1398 (bmo-pblex32) R 1395 1395 25521 34816 25544 4202496 4981 0 0 0 374 125 0 0 25 0 1 0 900596250 18604032 4255 1283457024 134512640 135887319 4286792384 18446744073709551615 135381649 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/1398/statm: 4542 4255 138 336 0 4204 0
Current children cumulated CPU time (s) 6.24
Current children cumulated vsize (KiB) 20736

[startup+12.7024 s]
/proc/loadavg: 1.15 1.17 1.09 2/39 1398
/proc/meminfo: memFree=295040/1048576 swapFree=2095372/2097144
[pid=1395] ppid=1394 vsize=2568 CPUtime=1.25
/proc/1395/stat : 1395 (cudf2pbo4user-1) S 1394 1395 25521 34816 25544 4202496 401 8842 0 0 0 0 107 18 20 0 1 0 900596122 2629632 280 1283457024 134512640 135304128 4294615440 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/1395/statm: 642 280 241 194 0 28 0
[pid=1398] ppid=1395 vsize=24264 CPUtime=11.36
/proc/1398/stat : 1398 (bmo-pblex32) R 1395 1395 25521 34816 25544 4202496 7339 0 0 0 974 162 0 0 25 0 1 0 900596250 24846336 5788 1283457024 134512640 135887319 4286792384 18446744073709551615 134617654 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/1398/statm: 6066 5788 144 336 0 5728 0
Current children cumulated CPU time (s) 12.61
Current children cumulated vsize (KiB) 26832

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

[startup+12.8125 s]
/proc/loadavg: 1.15 1.17 1.09 2/39 1398
/proc/meminfo: memFree=295040/1048576 swapFree=2095372/2097144
[pid=1395] ppid=1394 vsize=2568 CPUtime=1.25
/proc/1395/stat : 1395 (cudf2pbo4user-1) S 1394 1395 25521 34816 25544 4202496 401 8842 0 0 0 0 107 18 20 0 1 0 900596122 2629632 280 1283457024 134512640 135304128 4294615440 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/1395/statm: 642 280 241 194 0 28 0
[pid=1398] ppid=1395 vsize=24264 CPUtime=11.47
/proc/1398/stat : 1398 (bmo-pblex32) R 1395 1395 25521 34816 25544 4202496 7339 0 0 0 985 162 0 0 25 0 1 0 900596250 24846336 5788 1283457024 134512640 135887319 4286792384 18446744073709551615 134614896 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/1398/statm: 6066 5788 144 336 0 5728 0
Current children cumulated CPU time (s) 12.72
Current children cumulated vsize (KiB) 26832

[startup+16.0135 s]
/proc/loadavg: 1.15 1.17 1.09 2/39 1398
/proc/meminfo: memFree=283012/1048576 swapFree=2095372/2097144
[pid=1395] ppid=1394 vsize=2568 CPUtime=1.25
/proc/1395/stat : 1395 (cudf2pbo4user-1) S 1394 1395 25521 34816 25544 4202496 401 8842 0 0 0 0 107 18 20 0 1 0 900596122 2629632 280 1283457024 134512640 135304128 4294615440 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/1395/statm: 642 280 241 194 0 28 0
[pid=1398] ppid=1395 vsize=34676 CPUtime=14.65
/proc/1398/stat : 1398 (bmo-pblex32) R 1395 1395 25521 34816 25544 4202496 11431 0 0 0 1280 185 0 0 25 0 1 0 900596250 35508224 8447 1283457024 134512640 135887319 4286792384 18446744073709551615 135381649 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/1398/statm: 8669 8447 144 336 0 8331 0
Current children cumulated CPU time (s) 15.9
Current children cumulated vsize (KiB) 37244

[startup+16.8138 s]
/proc/loadavg: 1.15 1.17 1.09 2/39 1398
/proc/meminfo: memFree=281648/1048576 swapFree=2095372/2097144
[pid=1395] ppid=1394 vsize=2568 CPUtime=1.25
/proc/1395/stat : 1395 (cudf2pbo4user-1) S 1394 1395 25521 34816 25544 4202496 401 8842 0 0 0 0 107 18 20 0 1 0 900596122 2629632 280 1283457024 134512640 135304128 4294615440 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/1395/statm: 642 280 241 194 0 28 0
[pid=1398] ppid=1395 vsize=35624 CPUtime=15.43
/proc/1398/stat : 1398 (bmo-pblex32) R 1395 1395 25521 34816 25544 4202496 11681 0 0 0 1346 197 0 0 25 0 1 0 900596250 36478976 8693 1283457024 134512640 135887319 4286792384 18446744073709551615 134637884 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/1398/statm: 8906 8693 144 336 0 8568 0
Current children cumulated CPU time (s) 16.68
Current children cumulated vsize (KiB) 38192

[startup+17.2139 s]
/proc/loadavg: 1.15 1.17 1.09 2/39 1398
/proc/meminfo: memFree=281648/1048576 swapFree=2095372/2097144
[pid=1395] ppid=1394 vsize=2568 CPUtime=1.25
/proc/1395/stat : 1395 (cudf2pbo4user-1) S 1394 1395 25521 34816 25544 4202496 401 8842 0 0 0 0 107 18 20 0 1 0 900596122 2629632 280 1283457024 134512640 135304128 4294615440 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/1395/statm: 642 280 241 194 0 28 0
[pid=1398] ppid=1395 vsize=36160 CPUtime=15.82
/proc/1398/stat : 1398 (bmo-pblex32) R 1395 1395 25521 34816 25544 4202496 11789 0 0 0 1380 202 0 0 25 0 1 0 900596250 37027840 8801 1283457024 134512640 135887319 4286792384 18446744073709551615 134598364 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/1398/statm: 9040 8801 144 336 0 8702 0
Current children cumulated CPU time (s) 17.07
Current children cumulated vsize (KiB) 38728

[startup+17.604 s]
/proc/loadavg: 1.14 1.17 1.09 4/40 1400
/proc/meminfo: memFree=312508/1048576 swapFree=2095372/2097144
[pid=1395] ppid=1394 vsize=2568 CPUtime=17.42
/proc/1395/stat : 1395 (cudf2pbo4user-1) R 1394 1395 25521 34816 25544 4202496 420 20733 0 0 0 0 1519 223 18 0 1 0 900596122 2629632 280 1283457024 134512640 135304128 4294615440 18446744073709551615 4294960130 0 65538 4 82432 0 0 0 17 0 0 0 0
/proc/1395/statm: 642 280 241 194 0 28 0
[pid=1399] ppid=1395 vsize=1856 CPUtime=0
/proc/1399/stat : 1399 (grep) S 1395 1395 25521 34816 25544 4202496 323 0 0 0 0 0 0 0 18 0 1 0 900597878 1900544 202 1283457024 134512640 134613452 4291936176 18446744073709551615 4294960130 0 0 0 0 18446744071564457842 0 0 17 0 0 0 0
/proc/1399/statm: 464 202 137 25 0 81 0
[pid=1400] ppid=1395 vsize=8332 CPUtime=0.04
/proc/1400/stat : 1400 (sc.py) R 1395 1395 25521 34816 25544 4202496 1332 0 0 0 4 0 0 0 18 0 1 0 900597878 8531968 1147 1283457024 134512640 136476992 4293515584 18446744073709551615 134621280 0 0 16781312 2 0 0 0 17 0 0 0 0
/proc/1400/statm: 2083 1147 481 480 0 667 0
Current children cumulated CPU time (s) 17.46
Current children cumulated vsize (KiB) 12756

Child status: 0
Real time (s): 17.6155
CPU time (s): 17.4851
CPU user time (s): 15.245
CPU system time (s): 2.24014
CPU usage (%): 99.2594
Max. virtual memory (cumulated for all children) (KiB): 38996

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 15.245
system time used= 2.24014
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 22961
page faults= 0
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 14
involuntary context switches= 6008

runsolver used 0 second user time and 0 second system time

The end