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/aspcud-trendy-1.3/rand835640.cudf.impossible.log.runsolver ./aspcud-trendy-1.3 /home/misc2010/data/2010/impossible//rand835640.cudf /home/misc2010/tmp/201012070034/aspcud-trendy-1.3/rand835640.cudf.impossible.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.25 1.16 1.07 2/44 27615
/proc/meminfo: memFree=700948/1048576 swapFree=2077608/2097144
[pid=27615] ppid=27614 vsize=3028 CPUtime=0
/proc/27615/stat : 27615 (runsolver) D 27614 27615 4159 34819 4229 4202560 73 0 0 0 0 0 0 0 25 0 1 0 883212922 3100672 94 1283457024 134512640 134586868 4293515264 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0
/proc/27615/statm: 757 94 62 19 0 55 0

[startup+0.111056 s]
/proc/loadavg: 1.25 1.16 1.07 2/44 27615
/proc/meminfo: memFree=700948/1048576 swapFree=2077608/2097144
[pid=27615] ppid=27614 vsize=2596 CPUtime=0
/proc/27615/stat : 27615 (aspcud-trendy-1) S 27614 27615 4159 34819 4229 4202496 615 2214 0 3 0 0 0 0 25 0 1 0 883212922 2658304 299 1283457024 134512640 135304128 4290530800 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/27615/statm: 649 299 253 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.207051 s]
/proc/loadavg: 1.25 1.16 1.07 2/44 27615
/proc/meminfo: memFree=700948/1048576 swapFree=2077608/2097144
[pid=27615] ppid=27614 vsize=2596 CPUtime=0
/proc/27615/stat : 27615 (aspcud-trendy-1) S 27614 27615 4159 34819 4229 4202496 615 2214 0 3 0 0 0 0 25 0 1 0 883212922 2658304 299 1283457024 134512640 135304128 4290530800 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/27615/statm: 649 299 253 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.312898 s]
/proc/loadavg: 1.25 1.16 1.07 2/44 27615
/proc/meminfo: memFree=700948/1048576 swapFree=2077608/2097144
[pid=27615] ppid=27614 vsize=2596 CPUtime=0
/proc/27615/stat : 27615 (aspcud-trendy-1) S 27614 27615 4159 34819 4229 4202496 615 2214 0 3 0 0 0 0 25 0 1 0 883212922 2658304 299 1283457024 134512640 135304128 4290530800 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/27615/statm: 649 299 253 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.712988 s]
/proc/loadavg: 1.25 1.16 1.07 2/44 27615
/proc/meminfo: memFree=700948/1048576 swapFree=2077608/2097144
[pid=27615] ppid=27614 vsize=2596 CPUtime=0
/proc/27615/stat : 27615 (aspcud-trendy-1) S 27614 27615 4159 34819 4229 4202496 615 2214 0 3 0 0 0 0 25 0 1 0 883212922 2658304 299 1283457024 134512640 135304128 4290530800 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/27615/statm: 649 299 253 194 0 35 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+1.51319 s]
/proc/loadavg: 1.25 1.16 1.07 2/48 27629
/proc/meminfo: memFree=663132/1048576 swapFree=2077608/2097144
[pid=27615] ppid=27614 vsize=2596 CPUtime=0
/proc/27615/stat : 27615 (aspcud-trendy-1) S 27614 27615 4159 34819 4229 4202496 615 2214 0 3 0 0 0 0 25 0 1 0 883212922 2658304 299 1283457024 134512640 135304128 4290530800 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/27615/statm: 649 299 253 194 0 35 0
[pid=27627] ppid=27615 vsize=1872 CPUtime=0
/proc/27627/stat : 27627 (clasp) S 27615 27615 4159 34819 4229 4202496 268 0 16 0 0 0 0 0 23 0 1 0 883212927 1916928 153 1283457024 134512640 136223643 4291822864 18446744073709551615 135666734 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/27627/statm: 468 153 138 418 0 48 0
[pid=27628] ppid=27615 vsize=2608 CPUtime=0
/proc/27628/stat : 27628 (gringo) S 27615 27615 4159 34819 4229 4202496 384 0 23 0 0 0 0 0 23 0 1 0 883212927 2670592 277 1283457024 134512640 136959103 4289565744 18446744073709551615 135656590 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/27628/statm: 652 277 247 598 0 51 0
[pid=27629] ppid=27615 vsize=47452 CPUtime=1.22
/proc/27629/stat : 27629 (cudf2lp) R 27615 27615 4159 34819 4229 4202496 13193 0 14 0 119 3 0 0 25 0 1 0 883212927 48590848 11055 1283457024 134512640 135749571 4291823776 18446744073709551615 135180807 0 0 6 0 0 0 0 17 0 0 0 0
/proc/27629/statm: 11863 11055 127 302 0 11559 0
Current children cumulated CPU time (s) 1.22
Current children cumulated vsize (KiB) 54528

[startup+3.11357 s]
/proc/loadavg: 1.25 1.16 1.07 2/48 27629
/proc/meminfo: memFree=629348/1048576 swapFree=2077608/2097144
[pid=27615] ppid=27614 vsize=2596 CPUtime=0
/proc/27615/stat : 27615 (aspcud-trendy-1) S 27614 27615 4159 34819 4229 4202496 615 2214 0 3 0 0 0 0 25 0 1 0 883212922 2658304 299 1283457024 134512640 135304128 4290530800 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/27615/statm: 649 299 253 194 0 35 0
[pid=27627] ppid=27615 vsize=17804 CPUtime=0.07
/proc/27627/stat : 27627 (clasp) S 27615 27615 4159 34819 4229 4202496 4868 0 19 0 7 0 0 0 18 0 1 0 883212927 18231296 4098 1283457024 134512640 136223643 4291822864 18446744073709551615 135666734 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/27627/statm: 4451 4098 174 418 0 4031 0
[pid=27628] ppid=27615 vsize=25696 CPUtime=0.69
/proc/27628/stat : 27628 (gringo) R 27615 27615 4159 34819 4229 4202496 7822 0 23 0 66 3 0 0 18 0 1 0 883212927 26312704 4647 1283457024 134512640 136959103 4289565744 18446744073709551615 134598804 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/27628/statm: 6424 4647 247 598 0 5823 0
[pid=27629] ppid=27615 vsize=62352 CPUtime=2.04
/proc/27629/stat : 27629 (cudf2lp) R 27615 27615 4159 34819 4229 4202496 18987 0 14 0 196 8 0 0 25 0 1 0 883212927 63848448 15187 1283457024 134512640 135749571 4291823776 18446744073709551615 135237662 0 0 6 0 0 0 0 17 0 0 0 0
/proc/27629/statm: 15588 15187 129 302 0 15284 0
Current children cumulated CPU time (s) 2.8
Current children cumulated vsize (KiB) 108448

[startup+6.30763 s]
/proc/loadavg: 1.39 1.19 1.08 2/46 27629
/proc/meminfo: memFree=644760/1048576 swapFree=2077608/2097144
[pid=27615] ppid=27614 vsize=2596 CPUtime=4.69
/proc/27615/stat : 27615 (aspcud-trendy-1) S 27614 27615 4159 34819 4229 4202496 615 44303 0 41 0 0 446 23 18 0 1 0 883212922 2658304 299 1283457024 134512640 135304128 4290530800 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/27615/statm: 649 299 253 194 0 35 0
[pid=27627] ppid=27615 vsize=68716 CPUtime=1.29
/proc/27627/stat : 27627 (clasp) R 27615 27615 4159 34819 4229 4202496 19944 0 20 0 126 3 0 0 19 0 1 0 883212927 70365184 15832 1283457024 134512640 136223643 4291822864 18446744073709551615 134887186 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/27627/statm: 17179 15832 214 418 0 16759 0
Current children cumulated CPU time (s) 5.98
Current children cumulated vsize (KiB) 71312

[startup+12.7095 s]
/proc/loadavg: 1.36 1.19 1.08 2/46 27629
/proc/meminfo: memFree=633476/1048576 swapFree=2077608/2097144
[pid=27615] ppid=27614 vsize=2596 CPUtime=4.69
/proc/27615/stat : 27615 (aspcud-trendy-1) S 27614 27615 4159 34819 4229 4202496 615 44303 0 41 0 0 446 23 18 0 1 0 883212922 2658304 299 1283457024 134512640 135304128 4290530800 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/27615/statm: 649 299 253 194 0 35 0
[pid=27627] ppid=27615 vsize=67500 CPUtime=7.69
/proc/27627/stat : 27627 (clasp) R 27615 27615 4159 34819 4229 4202496 19994 0 20 0 766 3 0 0 25 0 1 0 883212927 69120000 15634 1283457024 134512640 136223643 4291822864 18446744073709551615 134704872 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/27627/statm: 16875 15634 225 418 0 16455 0
Current children cumulated CPU time (s) 12.38
Current children cumulated vsize (KiB) 70096

[startup+25.5024 s]
/proc/loadavg: 1.28 1.18 1.08 2/46 27629
/proc/meminfo: memFree=625416/1048576 swapFree=2077608/2097144
[pid=27615] ppid=27614 vsize=2596 CPUtime=4.69
/proc/27615/stat : 27615 (aspcud-trendy-1) S 27614 27615 4159 34819 4229 4202496 615 44303 0 41 0 0 446 23 18 0 1 0 883212922 2658304 299 1283457024 134512640 135304128 4290530800 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/27615/statm: 649 299 253 194 0 35 0
[pid=27627] ppid=27615 vsize=76064 CPUtime=20.45
/proc/27627/stat : 27627 (clasp) R 27615 27615 4159 34819 4229 4202496 22117 0 20 0 2040 5 0 0 25 0 1 0 883212927 77889536 17757 1283457024 134512640 136223643 4291822864 18446744073709551615 134929364 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/27627/statm: 19016 17757 225 418 0 18596 0
Current children cumulated CPU time (s) 25.14
Current children cumulated vsize (KiB) 78660

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

[startup+25.6124 s]
/proc/loadavg: 1.28 1.18 1.08 2/46 27629
/proc/meminfo: memFree=625416/1048576 swapFree=2077608/2097144
[pid=27615] ppid=27614 vsize=2596 CPUtime=4.69
/proc/27615/stat : 27615 (aspcud-trendy-1) S 27614 27615 4159 34819 4229 4202496 615 44303 0 41 0 0 446 23 18 0 1 0 883212922 2658304 299 1283457024 134512640 135304128 4290530800 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/27615/statm: 649 299 253 194 0 35 0
[pid=27627] ppid=27615 vsize=76064 CPUtime=20.56
/proc/27627/stat : 27627 (clasp) R 27615 27615 4159 34819 4229 4202496 22117 0 20 0 2051 5 0 0 25 0 1 0 883212927 77889536 17757 1283457024 134512640 136223643 4291822864 18446744073709551615 134664705 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/27627/statm: 19016 17757 225 418 0 18596 0
Current children cumulated CPU time (s) 25.25
Current children cumulated vsize (KiB) 78660

[startup+32.0136 s]
/proc/loadavg: 1.26 1.18 1.08 2/46 27629
/proc/meminfo: memFree=620208/1048576 swapFree=2077608/2097144
[pid=27615] ppid=27614 vsize=2596 CPUtime=4.69
/proc/27615/stat : 27615 (aspcud-trendy-1) S 27614 27615 4159 34819 4229 4202496 615 44303 0 41 0 0 446 23 18 0 1 0 883212922 2658304 299 1283457024 134512640 135304128 4290530800 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/27615/statm: 649 299 253 194 0 35 0
[pid=27627] ppid=27615 vsize=81344 CPUtime=26.97
/proc/27627/stat : 27627 (clasp) R 27615 27615 4159 34819 4229 4202496 23435 0 20 0 2690 7 0 0 25 0 1 0 883212927 83296256 19075 1283457024 134512640 136223643 4291822864 18446744073709551615 134906394 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/27627/statm: 20336 19075 225 418 0 19916 0
Current children cumulated CPU time (s) 31.66
Current children cumulated vsize (KiB) 83940

[startup+33.6139 s]
/proc/loadavg: 1.24 1.17 1.08 2/46 27629
/proc/meminfo: memFree=620208/1048576 swapFree=2077608/2097144
[pid=27615] ppid=27614 vsize=2596 CPUtime=4.69
/proc/27615/stat : 27615 (aspcud-trendy-1) S 27614 27615 4159 34819 4229 4202496 615 44303 0 41 0 0 446 23 18 0 1 0 883212922 2658304 299 1283457024 134512640 135304128 4290530800 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/27615/statm: 649 299 253 194 0 35 0
[pid=27627] ppid=27615 vsize=81344 CPUtime=28.57
/proc/27627/stat : 27627 (clasp) R 27615 27615 4159 34819 4229 4202496 23435 0 20 0 2850 7 0 0 25 0 1 0 883212927 83296256 19075 1283457024 134512640 136223643 4291822864 18446744073709551615 134924387 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/27627/statm: 20336 19075 225 418 0 19916 0
Current children cumulated CPU time (s) 33.26
Current children cumulated vsize (KiB) 83940

[startup+34.414 s]
/proc/loadavg: 1.24 1.17 1.08 2/46 27629
/proc/meminfo: memFree=620208/1048576 swapFree=2077608/2097144
[pid=27615] ppid=27614 vsize=2596 CPUtime=4.69
/proc/27615/stat : 27615 (aspcud-trendy-1) S 27614 27615 4159 34819 4229 4202496 615 44303 0 41 0 0 446 23 18 0 1 0 883212922 2658304 299 1283457024 134512640 135304128 4290530800 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/27615/statm: 649 299 253 194 0 35 0
[pid=27627] ppid=27615 vsize=81344 CPUtime=29.37
/proc/27627/stat : 27627 (clasp) R 27615 27615 4159 34819 4229 4202496 23435 0 20 0 2930 7 0 0 25 0 1 0 883212927 83296256 19075 1283457024 134512640 136223643 4291822864 18446744073709551615 134630044 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/27627/statm: 20336 19075 225 418 0 19916 0
Current children cumulated CPU time (s) 34.06
Current children cumulated vsize (KiB) 83940

[startup+35.2142 s]
/proc/loadavg: 1.24 1.17 1.08 2/46 27629
/proc/meminfo: memFree=620208/1048576 swapFree=2077608/2097144
[pid=27615] ppid=27614 vsize=2596 CPUtime=4.69
/proc/27615/stat : 27615 (aspcud-trendy-1) S 27614 27615 4159 34819 4229 4202496 615 44303 0 41 0 0 446 23 18 0 1 0 883212922 2658304 299 1283457024 134512640 135304128 4290530800 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/27615/statm: 649 299 253 194 0 35 0
[pid=27627] ppid=27615 vsize=81344 CPUtime=30.17
/proc/27627/stat : 27627 (clasp) R 27615 27615 4159 34819 4229 4202496 23435 0 20 0 3010 7 0 0 25 0 1 0 883212927 83296256 19075 1283457024 134512640 136223643 4291822864 18446744073709551615 134704900 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/27627/statm: 20336 19075 225 418 0 19916 0
Current children cumulated CPU time (s) 34.86
Current children cumulated vsize (KiB) 83940

[startup+35.6143 s]
/proc/loadavg: 1.24 1.17 1.08 2/46 27629
/proc/meminfo: memFree=620208/1048576 swapFree=2077608/2097144
[pid=27615] ppid=27614 vsize=2596 CPUtime=4.69
/proc/27615/stat : 27615 (aspcud-trendy-1) S 27614 27615 4159 34819 4229 4202496 615 44303 0 41 0 0 446 23 18 0 1 0 883212922 2658304 299 1283457024 134512640 135304128 4290530800 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/27615/statm: 649 299 253 194 0 35 0
[pid=27627] ppid=27615 vsize=81344 CPUtime=30.57
/proc/27627/stat : 27627 (clasp) R 27615 27615 4159 34819 4229 4202496 23435 0 20 0 3050 7 0 0 25 0 1 0 883212927 83296256 19075 1283457024 134512640 136223643 4291822864 18446744073709551615 134711214 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/27627/statm: 20336 19075 225 418 0 19916 0
Current children cumulated CPU time (s) 35.26
Current children cumulated vsize (KiB) 83940

[startup+35.7053 s]
/proc/loadavg: 1.24 1.17 1.08 2/46 27629
/proc/meminfo: memFree=620208/1048576 swapFree=2077608/2097144
[pid=27615] ppid=27614 vsize=2596 CPUtime=35.35
/proc/27615/stat : 27615 (aspcud-trendy-1) D 27614 27615 4159 34819 4229 4202496 615 67746 0 61 0 0 3503 32 18 0 1 0 883212922 2658304 299 1283457024 134512640 135304128 4290530800 18446744073709551615 4294960130 0 0 16902 1132543225 18446744071564252162 0 0 17 0 0 0 0
/proc/27615/statm: 649 299 253 194 0 35 0
Current children cumulated CPU time (s) 35.35
Current children cumulated vsize (KiB) 2596

Child status: 0
Real time (s): 35.745
CPU time (s): 35.3622
CPU user time (s): 35.0382
CPU system time (s): 0.32402
CPU usage (%): 98.929
Max. virtual memory (cumulated for all children) (KiB): 128300

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 35.0382
system time used= 0.32402
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 71973
page faults= 63
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 4019
involuntary context switches= 3608

runsolver used 0.004 second user time and 0 second system time

The end