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/201108241238/aspuncud-trendy-1.3/rand58.cudf.s-e-l.log.runsolver ./aspuncud-trendy-1.3 /home/misc2010/data/2011/incremental/s-e-l/rand58.cudf /home/misc2010/tmp/201108241238/aspuncud-trendy-1.3/rand58.cudf.s-e-l.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.00 1.01 1.00 4/36 15514
/proc/meminfo: memFree=564196/1048576 swapFree=0/0
[pid=15511] ppid=15510 vsize=2588 CPUtime=0
/proc/15511/stat : 15511 (aspuncud-trendy) S 15510 15511 1511 34817 1511 4202496 374 0 0 0 0 0 0 0 25 0 1 0 3594281 2650112 280 1283457024 134512640 135304128 4288357328 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/15511/statm: 647 280 234 194 0 34 0
[pid=15512] ppid=15511 vsize=2588 CPUtime=0
/proc/15512/stat : 15512 (aspuncud-trendy) S 15511 15511 1511 34817 1511 4202560 118 0 0 0 0 0 0 0 25 0 1 0 3594281 2650112 134 1283457024 134512640 135304128 4288357328 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0
/proc/15512/statm: 647 134 87 194 0 34 0
[pid=15513] ppid=15512 vsize=2588 CPUtime=0
/proc/15513/stat : 15513 (aspuncud-trendy) R 15512 15511 1511 34817 1511 4202560 127 0 0 0 0 0 0 0 25 0 1 0 3594281 2650112 151 1283457024 134512640 135304128 4288357328 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/15513/statm: 647 151 104 194 0 34 0
[pid=15514] ppid=15513 vsize=2588 CPUtime=0
/proc/15514/stat : 15514 (aspuncud-trendy) R 15513 15511 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 3594281 2650112 47 1283457024 134512640 135304128 4288357328 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/15514/statm: 647 47 0 194 0 34 0

[startup+0.194669 s]
/proc/loadavg: 1.00 1.01 1.00 4/36 15514
/proc/meminfo: memFree=564196/1048576 swapFree=0/0
[pid=15511] ppid=15510 vsize=2592 CPUtime=0.01
/proc/15511/stat : 15511 (aspuncud-trendy) S 15510 15511 1511 34817 1511 4202496 623 2226 0 0 0 1 0 0 25 0 1 0 3594281 2654208 298 1283457024 134512640 135304128 4288357328 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/15511/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+0.206663 s]
/proc/loadavg: 1.00 1.01 1.00 4/36 15514
/proc/meminfo: memFree=564196/1048576 swapFree=0/0
[pid=15511] ppid=15510 vsize=2592 CPUtime=0.01
/proc/15511/stat : 15511 (aspuncud-trendy) S 15510 15511 1511 34817 1511 4202496 623 2226 0 0 0 1 0 0 25 0 1 0 3594281 2654208 298 1283457024 134512640 135304128 4288357328 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/15511/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+0.307893 s]
/proc/loadavg: 1.00 1.01 1.00 4/36 15514
/proc/meminfo: memFree=564196/1048576 swapFree=0/0
[pid=15511] ppid=15510 vsize=2592 CPUtime=0.01
/proc/15511/stat : 15511 (aspuncud-trendy) S 15510 15511 1511 34817 1511 4202496 623 2226 0 0 0 1 0 0 25 0 1 0 3594281 2654208 298 1283457024 134512640 135304128 4288357328 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/15511/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+0.706703 s]
/proc/loadavg: 1.00 1.01 1.00 4/36 15514
/proc/meminfo: memFree=564196/1048576 swapFree=0/0
[pid=15511] ppid=15510 vsize=2592 CPUtime=0.01
/proc/15511/stat : 15511 (aspuncud-trendy) S 15510 15511 1511 34817 1511 4202496 623 2226 0 0 0 1 0 0 25 0 1 0 3594281 2654208 298 1283457024 134512640 135304128 4288357328 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/15511/statm: 648 298 251 194 0 35 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2592

[startup+1.50868 s]
/proc/loadavg: 1.00 1.01 1.00 2/37 15525
/proc/meminfo: memFree=522176/1048576 swapFree=0/0
[pid=15511] ppid=15510 vsize=2592 CPUtime=0.01
/proc/15511/stat : 15511 (aspuncud-trendy) S 15510 15511 1511 34817 1511 4202496 623 2226 0 0 0 1 0 0 25 0 1 0 3594281 2654208 298 1283457024 134512640 135304128 4288357328 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/15511/statm: 648 298 251 194 0 35 0
[pid=15523] ppid=15511 vsize=7352 CPUtime=0.02
/proc/15523/stat : 15523 (unclasp) R 15511 15511 1511 34817 1511 4202496 1477 0 0 0 1 1 0 0 18 0 1 0 3594282 7528448 1259 1283457024 134512640 135121179 4290004400 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/15523/statm: 1838 1259 275 149 0 1029 0
[pid=15524] ppid=15511 vsize=7648 CPUtime=0.17
/proc/15524/stat : 15524 (gringo) R 15511 15511 1511 34817 1511 4202496 1953 0 0 0 17 0 0 0 18 0 1 0 3594282 7831552 1404 1283457024 134512640 137056543 4290284928 18446744073709551615 134608465 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/15524/statm: 1912 1404 253 622 0 1287 0
[pid=15525] ppid=15511 vsize=30572 CPUtime=1.15
/proc/15525/stat : 15525 (cudf2lp) R 15511 15511 1511 34817 1511 4202496 10050 0 0 0 110 5 0 0 25 0 1 0 3594282 31305728 7426 1283457024 134512640 135786343 4293507344 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0
/proc/15525/statm: 7643 7426 137 311 0 7330 0
Current children cumulated CPU time (s) 1.35
Current children cumulated vsize (KiB) 48164

[startup+3.10918 s]
/proc/loadavg: 1.00 1.01 1.00 3/36 15525
/proc/meminfo: memFree=517852/1048576 swapFree=0/0
[pid=15511] ppid=15510 vsize=2592 CPUtime=2.09
/proc/15511/stat : 15511 (aspuncud-trendy) S 15510 15511 1511 34817 1511 4202496 623 20354 0 0 0 1 201 7 16 0 1 0 3594281 2654208 298 1283457024 134512640 135304128 4288357328 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/15511/statm: 648 298 251 194 0 35 0
[pid=15523] ppid=15511 vsize=30424 CPUtime=0.87
/proc/15523/stat : 15523 (unclasp) R 15511 15511 1511 34817 1511 4202496 11744 0 0 0 83 4 0 0 18 0 1 0 3594282 31154176 6725 1283457024 134512640 135121179 4290004400 18446744073709551615 134747603 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/15523/statm: 7606 6725 326 149 0 6797 0
Current children cumulated CPU time (s) 2.96
Current children cumulated vsize (KiB) 33016

[startup+6.31026 s]
/proc/loadavg: 1.00 1.01 1.00 2/35 15525
/proc/meminfo: memFree=524192/1048576 swapFree=0/0
[pid=15511] ppid=15510 vsize=2592 CPUtime=2.09
/proc/15511/stat : 15511 (aspuncud-trendy) S 15510 15511 1511 34817 1511 4202496 623 20354 0 0 0 1 201 7 16 0 1 0 3594281 2654208 298 1283457024 134512640 135304128 4288357328 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/15511/statm: 648 298 251 194 0 35 0
[pid=15523] ppid=15511 vsize=30708 CPUtime=4.08
/proc/15523/stat : 15523 (unclasp) R 15511 15511 1511 34817 1511 4202496 39478 0 0 0 388 20 0 0 25 0 1 0 3594282 31444992 6764 1283457024 134512640 135121179 4290004400 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/15523/statm: 7677 6764 326 149 0 6868 0
Current children cumulated CPU time (s) 6.17
Current children cumulated vsize (KiB) 33300

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

[startup+6.41027 s]
/proc/loadavg: 1.00 1.01 1.00 2/35 15525
/proc/meminfo: memFree=524192/1048576 swapFree=0/0
[pid=15511] ppid=15510 vsize=2592 CPUtime=2.09
/proc/15511/stat : 15511 (aspuncud-trendy) S 15510 15511 1511 34817 1511 4202496 623 20354 0 0 0 1 201 7 16 0 1 0 3594281 2654208 298 1283457024 134512640 135304128 4288357328 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/15511/statm: 648 298 251 194 0 35 0
[pid=15523] ppid=15511 vsize=30708 CPUtime=4.18
/proc/15523/stat : 15523 (unclasp) R 15511 15511 1511 34817 1511 4202496 40348 0 0 0 398 20 0 0 25 0 1 0 3594282 31444992 6764 1283457024 134512640 135121179 4290004400 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/15523/statm: 7677 6764 326 149 0 6868 0
Current children cumulated CPU time (s) 6.27
Current children cumulated vsize (KiB) 33300

[startup+9.61158 s]
/proc/loadavg: 1.00 1.01 1.00 2/35 15525
/proc/meminfo: memFree=524076/1048576 swapFree=0/0
[pid=15511] ppid=15510 vsize=2592 CPUtime=2.09
/proc/15511/stat : 15511 (aspuncud-trendy) S 15510 15511 1511 34817 1511 4202496 623 20354 0 0 0 1 201 7 16 0 1 0 3594281 2654208 298 1283457024 134512640 135304128 4288357328 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/15511/statm: 648 298 251 194 0 35 0
[pid=15523] ppid=15511 vsize=30784 CPUtime=7.37
/proc/15523/stat : 15523 (unclasp) R 15511 15511 1511 34817 1511 4202496 62420 0 0 0 706 31 0 0 25 0 1 0 3594282 31522816 6791 1283457024 134512640 135121179 4290004400 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/15523/statm: 7696 6791 333 149 0 6887 0
Current children cumulated CPU time (s) 9.46
Current children cumulated vsize (KiB) 33376

[startup+10.4119 s]
/proc/loadavg: 1.00 1.01 1.00 2/35 15525
/proc/meminfo: memFree=524324/1048576 swapFree=0/0
[pid=15511] ppid=15510 vsize=2592 CPUtime=2.09
/proc/15511/stat : 15511 (aspuncud-trendy) S 15510 15511 1511 34817 1511 4202496 623 20354 0 0 0 1 201 7 16 0 1 0 3594281 2654208 298 1283457024 134512640 135304128 4288357328 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/15511/statm: 648 298 251 194 0 35 0
[pid=15523] ppid=15511 vsize=31568 CPUtime=8.17
/proc/15523/stat : 15523 (unclasp) R 15511 15511 1511 34817 1511 4202496 68711 0 0 0 784 33 0 0 25 0 1 0 3594282 32325632 6987 1283457024 134512640 135121179 4290004400 18446744073709551615 134980958 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/15523/statm: 7892 6987 333 149 0 7083 0
Current children cumulated CPU time (s) 10.26
Current children cumulated vsize (KiB) 34160

[startup+11.2122 s]
/proc/loadavg: 1.00 1.01 1.00 2/35 15525
/proc/meminfo: memFree=524076/1048576 swapFree=0/0
[pid=15511] ppid=15510 vsize=2592 CPUtime=2.09
/proc/15511/stat : 15511 (aspuncud-trendy) S 15510 15511 1511 34817 1511 4202496 623 20354 0 0 0 1 201 7 16 0 1 0 3594281 2654208 298 1283457024 134512640 135304128 4288357328 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/15511/statm: 648 298 251 194 0 35 0
[pid=15523] ppid=15511 vsize=30988 CPUtime=8.96
/proc/15523/stat : 15523 (unclasp) R 15511 15511 1511 34817 1511 4202496 74951 0 0 0 860 36 0 0 25 0 1 0 3594282 31731712 6842 1283457024 134512640 135121179 4290004400 18446744073709551615 134891065 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/15523/statm: 7747 6842 333 149 0 6938 0
Current children cumulated CPU time (s) 11.05
Current children cumulated vsize (KiB) 33580

[startup+11.4123 s]
/proc/loadavg: 1.00 1.01 1.00 2/35 15525
/proc/meminfo: memFree=524076/1048576 swapFree=0/0
[pid=15511] ppid=15510 vsize=2592 CPUtime=2.09
/proc/15511/stat : 15511 (aspuncud-trendy) S 15510 15511 1511 34817 1511 4202496 623 20354 0 0 0 1 201 7 16 0 1 0 3594281 2654208 298 1283457024 134512640 135304128 4288357328 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/15511/statm: 648 298 251 194 0 35 0
[pid=15523] ppid=15511 vsize=31004 CPUtime=9.16
/proc/15523/stat : 15523 (unclasp) R 15511 15511 1511 34817 1511 4202496 76476 0 0 0 879 37 0 0 25 0 1 0 3594282 31748096 6878 1283457024 134512640 135121179 4290004400 18446744073709551615 134977774 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/15523/statm: 7751 6878 333 149 0 6942 0
Current children cumulated CPU time (s) 11.25
Current children cumulated vsize (KiB) 33596

[startup+11.5123 s]
/proc/loadavg: 1.00 1.01 1.00 2/35 15525
/proc/meminfo: memFree=524076/1048576 swapFree=0/0
[pid=15511] ppid=15510 vsize=2592 CPUtime=2.09
/proc/15511/stat : 15511 (aspuncud-trendy) S 15510 15511 1511 34817 1511 4202496 623 20354 0 0 0 1 201 7 16 0 1 0 3594281 2654208 298 1283457024 134512640 135304128 4288357328 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/15511/statm: 648 298 251 194 0 35 0
[pid=15523] ppid=15511 vsize=30784 CPUtime=9.26
/proc/15523/stat : 15523 (unclasp) R 15511 15511 1511 34817 1511 4202496 77241 0 0 0 889 37 0 0 25 0 1 0 3594282 31522816 6773 1283457024 134512640 135121179 4290004400 18446744073709551615 134643485 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/15523/statm: 7696 6773 333 149 0 6887 0
Current children cumulated CPU time (s) 11.35
Current children cumulated vsize (KiB) 33376

Child status: 0
Real time (s): 11.5597
CPU time (s): 11.4127
CPU user time (s): 10.9287
CPU system time (s): 0.48403
CPU usage (%): 98.7285
Max. virtual memory (cumulated for all children) (KiB): 61304

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 10.9287
system time used= 0.48403
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 100720
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= 1242
involuntary context switches= 1036

runsolver used 0 second user time and 0 second system time

The end