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/aspcud-trendy-1.5/rand609.cudf.user-upgrades.log.runsolver ./aspcud-trendy-1.5 /home/misc2010/data/2011/user-upgrades/rand609.cudf /home/misc2010/tmp/201108241238/aspcud-trendy-1.5/rand609.cudf.user-upgrades.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.03 1.06 1.07 5/36 23321
/proc/meminfo: memFree=316612/1048576 swapFree=0/0
[pid=23320] ppid=23319 vsize=2588 CPUtime=0
/proc/23320/stat : 23320 (aspcud-trendy-1) R 23319 23320 1511 34817 1511 4202496 365 0 0 0 0 0 0 0 25 0 1 0 4699726 2650112 279 1283457024 134512640 135304128 4293113952 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/23320/statm: 647 279 234 194 0 34 0
[pid=23321] ppid=23320 vsize=2588 CPUtime=0
/proc/23321/stat : 23321 (aspcud-trendy-1) R 23320 23320 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 4699726 2650112 45 1283457024 134512640 135304128 4293113952 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/23321/statm: 647 45 0 194 0 34 0

[startup+0.173865 s]
/proc/loadavg: 1.03 1.06 1.07 5/36 23321
/proc/meminfo: memFree=316612/1048576 swapFree=0/0
[pid=23320] ppid=23319 vsize=2596 CPUtime=0
/proc/23320/stat : 23320 (aspcud-trendy-1) S 23319 23320 1511 34817 1511 4202496 623 2230 0 0 0 0 0 0 25 0 1 0 4699726 2658304 298 1283457024 134512640 135304128 4293113952 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23320/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.20387 s]
/proc/loadavg: 1.03 1.06 1.07 5/36 23321
/proc/meminfo: memFree=316612/1048576 swapFree=0/0
[pid=23320] ppid=23319 vsize=2596 CPUtime=0
/proc/23320/stat : 23320 (aspcud-trendy-1) S 23319 23320 1511 34817 1511 4202496 623 2230 0 0 0 0 0 0 25 0 1 0 4699726 2658304 298 1283457024 134512640 135304128 4293113952 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23320/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.313897 s]
/proc/loadavg: 1.03 1.06 1.07 5/36 23321
/proc/meminfo: memFree=316612/1048576 swapFree=0/0
[pid=23320] ppid=23319 vsize=2596 CPUtime=0
/proc/23320/stat : 23320 (aspcud-trendy-1) S 23319 23320 1511 34817 1511 4202496 623 2230 0 0 0 0 0 0 25 0 1 0 4699726 2658304 298 1283457024 134512640 135304128 4293113952 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23320/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.713982 s]
/proc/loadavg: 1.03 1.06 1.07 5/36 23321
/proc/meminfo: memFree=316612/1048576 swapFree=0/0
[pid=23320] ppid=23319 vsize=2596 CPUtime=0
/proc/23320/stat : 23320 (aspcud-trendy-1) S 23319 23320 1511 34817 1511 4202496 623 2230 0 0 0 0 0 0 25 0 1 0 4699726 2658304 298 1283457024 134512640 135304128 4293113952 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23320/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+1.50415 s]
/proc/loadavg: 1.02 1.06 1.07 2/39 23335
/proc/meminfo: memFree=292132/1048576 swapFree=0/0
[pid=23320] ppid=23319 vsize=2596 CPUtime=0
/proc/23320/stat : 23320 (aspcud-trendy-1) S 23319 23320 1511 34817 1511 4202496 623 2230 0 0 0 0 0 0 25 0 1 0 4699726 2658304 298 1283457024 134512640 135304128 4293113952 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23320/statm: 649 298 251 194 0 36 0
[pid=23332] ppid=23320 vsize=1932 CPUtime=0.01
/proc/23332/stat : 23332 (clasp) S 23320 23320 1511 34817 1511 4202496 293 0 0 0 1 0 0 0 25 0 1 0 4699727 1978368 160 1283457024 134512640 136285277 4290229600 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/23332/statm: 483 160 144 433 0 48 0
[pid=23333] ppid=23320 vsize=2588 CPUtime=0
/proc/23333/stat : 23333 (gringo) S 23320 23320 1511 34817 1511 4202496 405 0 0 0 0 0 0 0 25 0 1 0 4699727 2650112 272 1283457024 134512640 136933539 4289527088 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/23333/statm: 647 272 242 592 0 52 0
[pid=23334] ppid=23320 vsize=25520 CPUtime=1.48
/proc/23334/stat : 23334 (cudf2lp) R 23320 23320 1511 34817 1511 4202496 7592 0 0 0 146 2 0 0 25 0 1 0 4699727 26132480 5742 1283457024 134512640 135786343 4286673552 18446744073709551615 135199569 0 0 6 0 0 0 0 17 0 0 0 0
/proc/23334/statm: 6380 5742 126 311 0 6067 0
Current children cumulated CPU time (s) 1.49
Current children cumulated vsize (KiB) 32636

[startup+3.10444 s]
/proc/loadavg: 1.02 1.06 1.07 2/39 23335
/proc/meminfo: memFree=270804/1048576 swapFree=0/0
[pid=23320] ppid=23319 vsize=2596 CPUtime=2.43
/proc/23320/stat : 23320 (aspcud-trendy-1) S 23319 23320 1511 34817 1511 4202496 624 15610 0 0 0 0 234 9 18 0 1 0 4699726 2658304 298 1283457024 134512640 135304128 4293113952 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23320/statm: 649 298 251 194 0 36 0
[pid=23332] ppid=23320 vsize=15872 CPUtime=0.06
/proc/23332/stat : 23332 (clasp) R 23320 23320 1511 34817 1511 4202496 4285 0 0 0 6 0 0 0 18 0 1 0 4699727 16252928 3630 1283457024 134512640 136285277 4290229600 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/23332/statm: 3968 3630 177 433 0 3533 0
[pid=23333] ppid=23320 vsize=25324 CPUtime=0.59
/proc/23333/stat : 23333 (gringo) R 23320 23320 1511 34817 1511 4202496 6630 0 0 0 58 1 0 0 18 0 1 0 4699727 25931776 4950 1283457024 134512640 136933539 4289527088 18446744073709551615 134612042 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/23333/statm: 6331 4950 253 592 0 5736 0
Current children cumulated CPU time (s) 3.08
Current children cumulated vsize (KiB) 43792

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

[startup+3.20446 s]
/proc/loadavg: 1.02 1.06 1.07 2/39 23335
/proc/meminfo: memFree=270804/1048576 swapFree=0/0
[pid=23320] ppid=23319 vsize=2596 CPUtime=2.43
/proc/23320/stat : 23320 (aspcud-trendy-1) S 23319 23320 1511 34817 1511 4202496 624 15610 0 0 0 0 234 9 18 0 1 0 4699726 2658304 298 1283457024 134512640 135304128 4293113952 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23320/statm: 649 298 251 194 0 36 0
[pid=23332] ppid=23320 vsize=17064 CPUtime=0.06
/proc/23332/stat : 23332 (clasp) R 23320 23320 1511 34817 1511 4202496 4577 0 0 0 6 0 0 0 18 0 1 0 4699727 17473536 3922 1283457024 134512640 136285277 4290229600 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/23332/statm: 4266 3922 177 433 0 3831 0
[pid=23333] ppid=23320 vsize=27924 CPUtime=0.69
/proc/23333/stat : 23333 (gringo) R 23320 23320 1511 34817 1511 4202496 7245 0 0 0 68 1 0 0 18 0 1 0 4699727 28594176 5565 1283457024 134512640 136933539 4289527088 18446744073709551615 136204813 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/23333/statm: 6981 5565 253 592 0 6386 0
Current children cumulated CPU time (s) 3.18
Current children cumulated vsize (KiB) 47584

[startup+4.00462 s]
/proc/loadavg: 1.02 1.06 1.07 3/38 23335
/proc/meminfo: memFree=272804/1048576 swapFree=0/0
[pid=23320] ppid=23319 vsize=2596 CPUtime=3.24
/proc/23320/stat : 23320 (aspcud-trendy-1) S 23319 23320 1511 34817 1511 4202496 624 23922 0 0 0 0 314 10 15 0 1 0 4699726 2658304 298 1283457024 134512640 135304128 4293113952 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23320/statm: 649 298 251 194 0 36 0
[pid=23332] ppid=23320 vsize=25404 CPUtime=0.74
/proc/23332/stat : 23332 (clasp) R 23320 23320 1511 34817 1511 4202496 7187 0 0 0 74 0 0 0 18 0 1 0 4699727 26013696 6079 1283457024 134512640 136285277 4290229600 18446744073709551615 134615093 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/23332/statm: 6351 6079 234 433 0 5916 0
Current children cumulated CPU time (s) 3.98
Current children cumulated vsize (KiB) 28000

[startup+4.20464 s]
/proc/loadavg: 1.02 1.06 1.07 3/38 23335
/proc/meminfo: memFree=272804/1048576 swapFree=0/0
[pid=23320] ppid=23319 vsize=2596 CPUtime=3.24
/proc/23320/stat : 23320 (aspcud-trendy-1) S 23319 23320 1511 34817 1511 4202496 624 23922 0 0 0 0 314 10 15 0 1 0 4699726 2658304 298 1283457024 134512640 135304128 4293113952 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/23320/statm: 649 298 251 194 0 36 0
[pid=23332] ppid=23320 vsize=25404 CPUtime=0.94
/proc/23332/stat : 23332 (clasp) R 23320 23320 1511 34817 1511 4202496 7187 0 0 0 94 0 0 0 19 0 1 0 4699727 26013696 6079 1283457024 134512640 136285277 4290229600 18446744073709551615 134931889 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/23332/statm: 6351 6079 234 433 0 5916 0
Current children cumulated CPU time (s) 4.18
Current children cumulated vsize (KiB) 28000

Child status: 0
Real time (s): 4.27138
CPU time (s): 4.26827
CPU user time (s): 4.14026
CPU system time (s): 0.128008
CPU usage (%): 99.9272
Max. virtual memory (cumulated for all children) (KiB): 62764

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 4.14026
system time used= 0.128008
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 35390
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= 921
involuntary context switches= 685

runsolver used 0 second user time and 0 second system time

The end