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/201103031013/aspcud-trendy-1.4/3922.cudf.caixa.log.runsolver ./aspcud-trendy-1.4 /home/misc2010/data/misc4/caixa//3922.cudf /home/misc2010/tmp/201103031013/aspcud-trendy-1.4/3922.cudf.caixa.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.81 1.76 1.64 5/38 14400
/proc/meminfo: memFree=290464/1048576 swapFree=0/0
[pid=14387] ppid=14386 vsize=2588 CPUtime=0.01
/proc/14387/stat : 14387 (aspcud-trendy-1) R 14386 14387 29493 34817 29493 4202496 584 2227 0 0 0 0 0 1 25 0 1 0 76009434 2650112 296 1283457024 134512640 135304128 4291628816 18446744073709551615 4294960130 0 65538 4 1132560123 0 0 0 17 0 0 0 0
/proc/14387/statm: 647 296 250 194 0 34 0
[pid=14398] ppid=14387 vsize=2588 CPUtime=0
/proc/14398/stat : 14398 (aspcud-trendy-1) R 14387 14387 29493 34817 29493 4202560 109 0 0 0 0 0 0 0 25 0 1 0 76009435 2650112 130 1283457024 134512640 135304128 4291628816 18446744073709551615 4294960130 0 0 6 1132494585 0 0 0 17 0 0 0 0
/proc/14398/statm: 647 130 83 194 0 34 0
[pid=14399] ppid=14387 vsize=2588 CPUtime=0
/proc/14399/stat : 14399 (aspcud-trendy-1) S 14387 14387 29493 34817 29493 4202560 108 0 0 0 0 0 0 0 25 0 1 0 76009435 2650112 130 1283457024 134512640 135304128 4291628816 18446744073709551615 4294960130 0 0 6 1132494585 18446744071564457842 0 0 17 0 0 0 0
/proc/14399/statm: 647 130 83 194 0 34 0
[pid=14400] ppid=14387 vsize=2588 CPUtime=0
/proc/14400/stat : 14400 (aspcud-trendy-1) R 14387 14387 29493 34817 29493 4202560 0 0 0 0 0 0 0 0 25 0 1 0 76009435 2650112 46 1283457024 134512640 135304128 4291628816 18446744073709551615 4294960130 0 65538 4 1132560123 0 0 0 17 0 0 0 0
/proc/14400/statm: 647 46 0 194 0 34 0

[startup+0.168696 s]
/proc/loadavg: 1.81 1.76 1.64 5/38 14400
/proc/meminfo: memFree=290464/1048576 swapFree=0/0
[pid=14387] ppid=14386 vsize=2588 CPUtime=0.01
/proc/14387/stat : 14387 (aspcud-trendy-1) S 14386 14387 29493 34817 29493 4202496 609 2227 0 0 0 0 0 1 25 0 1 0 76009434 2650112 297 1283457024 134512640 135304128 4291628816 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14387/statm: 647 297 251 194 0 34 0
[pid=14398] ppid=14387 vsize=1892 CPUtime=0
/proc/14398/stat : 14398 (clasp) S 14387 14387 29493 34817 29493 4202496 287 0 0 0 0 0 0 0 25 0 1 0 76009435 1937408 156 1283457024 134512640 136241547 4287345312 18446744073709551615 135683070 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/14398/statm: 473 156 140 423 0 48 0
[pid=14399] ppid=14387 vsize=2604 CPUtime=0
/proc/14399/stat : 14399 (gringo) S 14387 14387 29493 34817 29493 4202496 406 0 0 0 0 0 0 0 25 0 1 0 76009435 2666496 276 1283457024 134512640 136959103 4291673920 18446744073709551615 135656590 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/14399/statm: 651 276 247 598 0 50 0
[pid=14400] ppid=14387 vsize=7948 CPUtime=0.1
/proc/14400/stat : 14400 (cudf2lp) R 14387 14387 29493 34817 29493 4202496 1966 0 0 0 8 2 0 0 25 0 1 0 76009435 8138752 1738 1283457024 134512640 135749763 4294531600 18446744073709551615 134606334 0 0 6 0 0 0 0 17 0 0 0 0
/proc/14400/statm: 1987 1738 119 303 0 1682 0
Current children cumulated CPU time (s) 0.11
Current children cumulated vsize (KiB) 15032

[startup+0.204707 s]
/proc/loadavg: 1.81 1.76 1.64 5/38 14400
/proc/meminfo: memFree=290464/1048576 swapFree=0/0
[pid=14387] ppid=14386 vsize=2588 CPUtime=0.01
/proc/14387/stat : 14387 (aspcud-trendy-1) S 14386 14387 29493 34817 29493 4202496 609 2227 0 0 0 0 0 1 25 0 1 0 76009434 2650112 297 1283457024 134512640 135304128 4291628816 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14387/statm: 647 297 251 194 0 34 0
[pid=14398] ppid=14387 vsize=1892 CPUtime=0
/proc/14398/stat : 14398 (clasp) S 14387 14387 29493 34817 29493 4202496 287 0 0 0 0 0 0 0 25 0 1 0 76009435 1937408 156 1283457024 134512640 136241547 4287345312 18446744073709551615 135683070 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/14398/statm: 473 156 140 423 0 48 0
[pid=14399] ppid=14387 vsize=2604 CPUtime=0
/proc/14399/stat : 14399 (gringo) S 14387 14387 29493 34817 29493 4202496 406 0 0 0 0 0 0 0 25 0 1 0 76009435 2666496 276 1283457024 134512640 136959103 4291673920 18446744073709551615 135656590 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/14399/statm: 651 276 247 598 0 50 0
[pid=14400] ppid=14387 vsize=12328 CPUtime=0.13
/proc/14400/stat : 14400 (cudf2lp) R 14387 14387 29493 34817 29493 4202496 3100 0 0 0 11 2 0 0 25 0 1 0 76009435 12623872 2743 1283457024 134512640 135749763 4294531600 18446744073709551615 135170611 0 0 6 0 0 0 0 17 0 0 0 0
/proc/14400/statm: 3082 2743 119 303 0 2777 0
Current children cumulated CPU time (s) 0.14
Current children cumulated vsize (KiB) 19412

[startup+0.304708 s]
/proc/loadavg: 1.81 1.76 1.64 5/38 14400
/proc/meminfo: memFree=290464/1048576 swapFree=0/0
[pid=14387] ppid=14386 vsize=2588 CPUtime=0.01
/proc/14387/stat : 14387 (aspcud-trendy-1) S 14386 14387 29493 34817 29493 4202496 609 2227 0 0 0 0 0 1 25 0 1 0 76009434 2650112 297 1283457024 134512640 135304128 4291628816 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14387/statm: 647 297 251 194 0 34 0
[pid=14398] ppid=14387 vsize=1892 CPUtime=0
/proc/14398/stat : 14398 (clasp) S 14387 14387 29493 34817 29493 4202496 287 0 0 0 0 0 0 0 25 0 1 0 76009435 1937408 156 1283457024 134512640 136241547 4287345312 18446744073709551615 135683070 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/14398/statm: 473 156 140 423 0 48 0
[pid=14399] ppid=14387 vsize=2604 CPUtime=0
/proc/14399/stat : 14399 (gringo) S 14387 14387 29493 34817 29493 4202496 406 0 0 0 0 0 0 0 25 0 1 0 76009435 2666496 276 1283457024 134512640 136959103 4291673920 18446744073709551615 135656590 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/14399/statm: 651 276 247 598 0 50 0
[pid=14400] ppid=14387 vsize=13256 CPUtime=0.23
/proc/14400/stat : 14400 (cudf2lp) R 14387 14387 29493 34817 29493 4202496 3428 0 0 0 20 3 0 0 25 0 1 0 76009435 13574144 3022 1283457024 134512640 135749763 4294531600 18446744073709551615 134612256 0 0 6 0 0 0 0 17 0 0 0 0
/proc/14400/statm: 3314 3022 119 303 0 3009 0
Current children cumulated CPU time (s) 0.24
Current children cumulated vsize (KiB) 20340

[startup+0.706151 s]
/proc/loadavg: 1.81 1.76 1.64 5/38 14400
/proc/meminfo: memFree=290464/1048576 swapFree=0/0
[pid=14387] ppid=14386 vsize=2588 CPUtime=0.01
/proc/14387/stat : 14387 (aspcud-trendy-1) S 14386 14387 29493 34817 29493 4202496 609 2227 0 0 0 0 0 1 25 0 1 0 76009434 2650112 297 1283457024 134512640 135304128 4291628816 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14387/statm: 647 297 251 194 0 34 0
[pid=14398] ppid=14387 vsize=2292 CPUtime=0
/proc/14398/stat : 14398 (clasp) S 14387 14387 29493 34817 29493 4202496 419 0 0 0 0 0 0 0 19 0 1 0 76009435 2347008 288 1283457024 134512640 136241547 4287345312 18446744073709551615 135683070 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/14398/statm: 573 288 174 423 0 148 0
[pid=14399] ppid=14387 vsize=3252 CPUtime=0.02
/proc/14399/stat : 14399 (gringo) R 14387 14387 29493 34817 29493 4202496 548 0 0 0 2 0 0 0 19 0 1 0 76009435 3330048 418 1283457024 134512640 136959103 4291673920 18446744073709551615 136227615 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/14399/statm: 813 418 247 598 0 212 0
[pid=14400] ppid=14387 vsize=36376 CPUtime=0.59
/proc/14400/stat : 14400 (cudf2lp) R 14387 14387 29493 34817 29493 4202496 9937 0 0 0 54 5 0 0 25 0 1 0 76009435 37249024 8854 1283457024 134512640 135749763 4294531600 18446744073709551615 135237662 0 0 6 0 0 0 0 17 0 0 0 0
/proc/14400/statm: 9094 8854 128 303 0 8789 0
Current children cumulated CPU time (s) 0.62
Current children cumulated vsize (KiB) 44508

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

[startup+0.806199 s]
/proc/loadavg: 1.81 1.76 1.64 5/38 14400
/proc/meminfo: memFree=290464/1048576 swapFree=0/0
[pid=14387] ppid=14386 vsize=2588 CPUtime=0.01
/proc/14387/stat : 14387 (aspcud-trendy-1) S 14386 14387 29493 34817 29493 4202496 609 2227 0 0 0 0 0 1 25 0 1 0 76009434 2650112 297 1283457024 134512640 135304128 4291628816 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14387/statm: 647 297 251 194 0 34 0
[pid=14398] ppid=14387 vsize=3428 CPUtime=0.01
/proc/14398/stat : 14398 (clasp) S 14387 14387 29493 34817 29493 4202496 704 0 0 0 1 0 0 0 18 0 1 0 76009435 3510272 573 1283457024 134512640 136241547 4287345312 18446744073709551615 135683070 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/14398/statm: 857 573 174 423 0 432 0
[pid=14399] ppid=14387 vsize=4844 CPUtime=0.08
/proc/14399/stat : 14399 (gringo) R 14387 14387 29493 34817 29493 4202496 1022 0 0 0 7 1 0 0 19 0 1 0 76009435 4960256 745 1283457024 134512640 136959103 4291673920 18446744073709551615 135656494 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/14399/statm: 1211 745 247 598 0 610 0
[pid=14400] ppid=14387 vsize=36376 CPUtime=0.6
/proc/14400/stat : 14400 (cudf2lp) R 14387 14387 29493 34817 29493 4202496 9937 0 0 0 55 5 0 0 25 0 1 0 76009435 37249024 8854 1283457024 134512640 135749763 4294531600 18446744073709551615 135237662 0 0 6 0 0 0 0 17 0 0 0 0
/proc/14400/statm: 9094 8854 128 303 0 8789 0
Current children cumulated CPU time (s) 0.7
Current children cumulated vsize (KiB) 47236

[startup+1.20632 s]
/proc/loadavg: 1.81 1.76 1.64 3/38 14402
/proc/meminfo: memFree=267644/1048576 swapFree=0/0
[pid=14387] ppid=14386 vsize=2588 CPUtime=0.75
/proc/14387/stat : 14387 (aspcud-trendy-1) S 14386 14387 29493 34817 29493 4202496 609 12168 0 0 0 0 68 7 18 0 1 0 76009434 2650112 297 1283457024 134512640 135304128 4291628816 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14387/statm: 647 297 251 194 0 34 0
[pid=14398] ppid=14387 vsize=10040 CPUtime=0.06
/proc/14398/stat : 14398 (clasp) R 14387 14387 29493 34817 29493 4202496 2557 0 0 0 6 0 0 0 18 0 1 0 76009435 10280960 2222 1283457024 134512640 136241547 4287345312 18446744073709551615 134852635 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/14398/statm: 2510 2222 175 423 0 2085 0
[pid=14399] ppid=14387 vsize=15520 CPUtime=0.29
/proc/14399/stat : 14399 (gringo) R 14387 14387 29493 34817 29493 4202496 3755 0 0 0 27 2 0 0 18 0 1 0 76009435 15892480 2995 1283457024 134512640 136959103 4291673920 18446744073709551615 135656494 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/14399/statm: 3880 2995 256 598 0 3279 0
Current children cumulated CPU time (s) 1.1
Current children cumulated vsize (KiB) 28148

[startup+1.40638 s]
/proc/loadavg: 1.81 1.76 1.64 3/38 14402
/proc/meminfo: memFree=267644/1048576 swapFree=0/0
[pid=14387] ppid=14386 vsize=2588 CPUtime=0.75
/proc/14387/stat : 14387 (aspcud-trendy-1) S 14386 14387 29493 34817 29493 4202496 609 12168 0 0 0 0 68 7 18 0 1 0 76009434 2650112 297 1283457024 134512640 135304128 4291628816 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/14387/statm: 647 297 251 194 0 34 0
[pid=14398] ppid=14387 vsize=13544 CPUtime=0.08
/proc/14398/stat : 14398 (clasp) R 14387 14387 29493 34817 29493 4202496 3482 0 0 0 8 0 0 0 18 0 1 0 76009435 13869056 3056 1283457024 134512640 136241547 4287345312 18446744073709551615 135683070 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/14398/statm: 3386 3056 177 423 0 2961 0
[pid=14399] ppid=14387 vsize=13900 CPUtime=0.47
/proc/14399/stat : 14399 (gringo) R 14387 14387 29493 34817 29493 4202496 4872 0 0 0 44 3 0 0 18 0 1 0 76009435 14233600 2928 1283457024 134512640 136959103 4291673920 18446744073709551615 134602074 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/14399/statm: 3475 2928 259 598 0 2874 0
Current children cumulated CPU time (s) 1.3
Current children cumulated vsize (KiB) 30032

Child status: 0
Real time (s): 1.48766
CPU time (s): 1.40409
CPU user time (s): 1.24008
CPU system time (s): 0.16401
CPU usage (%): 94.3823
Max. virtual memory (cumulated for all children) (KiB): 50172

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 1.24008
system time used= 0.16401
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 34376
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= 677
involuntary context switches= 567

runsolver used 0 second user time and 0.008 second system time

The end