stan-dev / stan-dev/rstan

repeated calls to optimizing() sometimes get stuck

Open
#685 0 comments 0 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

Dominant language
R
Stars
1.1k
Forks
266
Avg merge
2h 56m
Merged PRs (30d)
1

Description

Summary:

When calling optimizing repeatedly, R occasionally gets stuck. It is more likely to happen when making large number of calls.

Description:

We have a function func doing the following things:

  1. Sample from a stan model, with sampling, and obtain sampled data to construct a list lst;
  2. Call optimizing three times with data=lst.

func is called sequentially for hundreds of times. We observed that sometimes optimizing seems to return, but the program does not continue with execution.

Reproducible Steps:

We added a print statement in stan model block to see whether optimizing actually returns. Here's the latest output before the program hangs:

SAMPLING FOR MODEL 'stan_generic_normal_0' NOW (CHAIN 1).
Chain 1: 
Chain 1: Gradient evaluation took 9e-06 seconds
Chain 1: 1000 transitions using 10 leapfrog steps per transition would take 0.09 seconds.
Chain 1: Adjust your expectations accordingly!
Chain 1: 
Chain 1: 
Chain 1: Iteration:    1 / 2000 [  0%]  (Warmup)
Chain 1: Iteration:  200 / 2000 [ 10%]  (Warmup)
Chain 1: Iteration:  400 / 2000 [ 20%]  (Warmup)
Chain 1: Iteration:  600 / 2000 [ 30%]  (Warmup)
Chain 1: Iteration:  800 / 2000 [ 40%]  (Warmup)
Chain 1: Iteration: 1000 / 2000 [ 50%]  (Warmup)
Chain 1: Iteration: 1001 / 2000 [ 50%]  (Sampling)
Chain 1: Iteration: 1200 / 2000 [ 60%]  (Sampling)
Chain 1: Iteration: 1400 / 2000 [ 70%]  (Sampling)
Chain 1: Iteration: 1600 / 2000 [ 80%]  (Sampling)
Chain 1: Iteration: 1800 / 2000 [ 90%]  (Sampling)
Chain 1: Iteration: 2000 / 2000 [100%]  (Sampling)
Chain 1: 
Chain 1:  Elapsed Time: 0.005852 seconds (Warm-up)
Chain 1:                0.005538 seconds (Sampling)
Chain 1:                0.01139 seconds (Total)
Chain 1: 

SAMPLING FOR MODEL 'stan_generic_normal_0' NOW (CHAIN 2).
Chain 2: 
Chain 2: Gradient evaluation took 8e-06 seconds
Chain 2: 1000 transitions using 10 leapfrog steps per transition would take 0.08 seconds.
Chain 2: Adjust your expectations accordingly!
Chain 2: 
Chain 2: 
Chain 2: Iteration:    1 / 2000 [  0%]  (Warmup)
Chain 2: Iteration:  200 / 2000 [ 10%]  (Warmup)
Chain 2: Iteration:  400 / 2000 [ 20%]  (Warmup)
Chain 2: Iteration:  600 / 2000 [ 30%]  (Warmup)
Chain 2: Iteration:  800 / 2000 [ 40%]  (Warmup)
Chain 2: Iteration: 1000 / 2000 [ 50%]  (Warmup)
Chain 2: Iteration: 1001 / 2000 [ 50%]  (Sampling)
Chain 2: Iteration: 1200 / 2000 [ 60%]  (Sampling)
Chain 2: Iteration: 1400 / 2000 [ 70%]  (Sampling)
Chain 2: Iteration: 1600 / 2000 [ 80%]  (Sampling)
Chain 2: Iteration: 1800 / 2000 [ 90%]  (Sampling)
Chain 2: Iteration: 2000 / 2000 [100%]  (Sampling)
Chain 2: 
Chain 2:  Elapsed Time: 0.005662 seconds (Warm-up)
Chain 2:                0.005962 seconds (Sampling)
Chain 2:                0.011624 seconds (Total)
Chain 2: 

SAMPLING FOR MODEL 'stan_generic_normal_0' NOW (CHAIN 3).
Chain 3: 
Chain 3: Gradient evaluation took 8e-06 seconds
Chain 3: 1000 transitions using 10 leapfrog steps per transition would take 0.08 seconds.
Chain 3: Adjust your expectations accordingly!
Chain 3: 
Chain 3: 
Chain 3: Iteration:    1 / 2000 [  0%]  (Warmup)
Chain 3: Iteration:  200 / 2000 [ 10%]  (Warmup)
Chain 3: Iteration:  400 / 2000 [ 20%]  (Warmup)
Chain 3: Iteration:  600 / 2000 [ 30%]  (Warmup)
Chain 3: Iteration:  800 / 2000 [ 40%]  (Warmup)
Chain 3: Iteration: 1000 / 2000 [ 50%]  (Warmup)
Chain 3: Iteration: 1001 / 2000 [ 50%]  (Sampling)
Chain 3: Iteration: 1200 / 2000 [ 60%]  (Sampling)
Chain 3: Iteration: 1400 / 2000 [ 70%]  (Sampling)
Chain 3: Iteration: 1600 / 2000 [ 80%]  (Sampling)
Chain 3: Iteration: 1800 / 2000 [ 90%]  (Sampling)
Chain 3: Iteration: 2000 / 2000 [100%]  (Sampling)
Chain 3: 
Chain 3:  Elapsed Time: 0.005503 seconds (Warm-up)
Chain 3:                0.005484 seconds (Sampling)
Chain 3:                0.010987 seconds (Total)
Chain 3: 

SAMPLING FOR MODEL 'stan_generic_normal_0' NOW (CHAIN 4).
Chain 4: 
Chain 4: Gradient evaluation took 8e-06 seconds
Chain 4: 1000 transitions using 10 leapfrog steps per transition would take 0.08 seconds.
Chain 4: Adjust your expectations accordingly!
Chain 4: 
Chain 4: 
Chain 4: Iteration:    1 / 2000 [  0%]  (Warmup)
Chain 4: Iteration:  200 / 2000 [ 10%]  (Warmup)
Chain 4: Iteration:  400 / 2000 [ 20%]  (Warmup)
Chain 4: Iteration:  600 / 2000 [ 30%]  (Warmup)
Chain 4: Iteration:  800 / 2000 [ 40%]  (Warmup)
Chain 4: Iteration: 1000 / 2000 [ 50%]  (Warmup)
Chain 4: Iteration: 1001 / 2000 [ 50%]  (Sampling)
Chain 4: Iteration: 1200 / 2000 [ 60%]  (Sampling)
Chain 4: Iteration: 1400 / 2000 [ 70%]  (Sampling)
Chain 4: Iteration: 1600 / 2000 [ 80%]  (Sampling)
Chain 4: Iteration: 1800 / 2000 [ 90%]  (Sampling)
Chain 4: Iteration: 2000 / 2000 [100%]  (Sampling)
Chain 4: 
Chain 4:  Elapsed Time: 0.005756 seconds (Warm-up)
Chain 4:                0.004939 seconds (Sampling)
Chain 4:                0.010695 seconds (Total)
Chain 4: 
[1] "divergence %: 0"
2019-08-20 17:02:06 INFO::Optimizing...
Chain 1: 1

Chain 1: 1

Chain 1: Initial log joint probability = -0.215946
Chain 1:     Iter      log prob        ||dx||      ||grad||       alpha      alpha0  # evals  Notes 
Chain 1: 1
1
1
1
1
1
1

We used pstrace to track what the R process does. These are the last few sys calls from the process:

getcwd("/root/dev/model/analytics", 4096) = 26
getcwd("/root/dev/model/analytics", 4096) = 26
getrusage(RUSAGE_SELF, {ru_utime={tv_sec=2018, tv_usec=748000}, ru_stime={tv_sec=69, tv_usec=964000}, ...}) = 0
getrusage(RUSAGE_CHILDREN, {ru_utime={tv_sec=40, tv_usec=860000}, ru_stime={tv_sec=1, tv_usec=244000}, ...}) = 0
getrusage(RUSAGE_SELF, {ru_utime={tv_sec=2018, tv_usec=748000}, ru_stime={tv_sec=69, tv_usec=964000}, ...}) = 0
getrusage(RUSAGE_CHILDREN, {ru_utime={tv_sec=40, tv_usec=860000}, ru_stime={tv_sec=1, tv_usec=244000}, ...}) = 0
getrusage(RUSAGE_SELF, {ru_utime={tv_sec=2018, tv_usec=748000}, ru_stime={tv_sec=69, tv_usec=964000}, ...}) = 0
getrusage(RUSAGE_CHILDREN, {ru_utime={tv_sec=40, tv_usec=860000}, ru_stime={tv_sec=1, tv_usec=244000}, ...}) = 0
getrusage(RUSAGE_SELF, {ru_utime={tv_sec=2018, tv_usec=748000}, ru_stime={tv_sec=69, tv_usec=964000}, ...}) = 0
getrusage(RUSAGE_CHILDREN, {ru_utime={tv_sec=40, tv_usec=860000}, ru_stime={tv_sec=1, tv_usec=244000}, ...}) = 0
getrusage(RUSAGE_SELF, {ru_utime={tv_sec=2018, tv_usec=748000}, ru_stime={tv_sec=69, tv_usec=964000}, ...}) = 0
getrusage(RUSAGE_CHILDREN, {ru_utime={tv_sec=40, tv_usec=860000}, ru_stime={tv_sec=1, tv_usec=244000}, ...}) = 0
getrusage(RUSAGE_SELF, {ru_utime={tv_sec=2018, tv_usec=752000}, ru_stime={tv_sec=69, tv_usec=964000}, ...}) = 0
getrusage(RUSAGE_CHILDREN, {ru_utime={tv_sec=40, tv_usec=860000}, ru_stime={tv_sec=1, tv_usec=244000}, ...}) = 0
getrusage(RUSAGE_SELF, {ru_utime={tv_sec=2018, tv_usec=760000}, ru_stime={tv_sec=69, tv_usec=964000}, ...}) = 0
getrusage(RUSAGE_CHILDREN, {ru_utime={tv_sec=40, tv_usec=860000}, ru_stime={tv_sec=1, tv_usec=244000}, ...}) = 0
getrusage(RUSAGE_SELF, {ru_utime={tv_sec=2018, tv_usec=760000}, ru_stime={tv_sec=69, tv_usec=964000}, ...}) = 0
getrusage(RUSAGE_CHILDREN, {ru_utime={tv_sec=40, tv_usec=860000}, ru_stime={tv_sec=1, tv_usec=244000}, ...}) = 0
write(1, "Chain ", 6)                   = 6
write(1, "1", 1)                        = 1
write(1, ": ", 2)                       = 2
write(1, "1\n", 2)                      = 2
write(1, "\n", 1)                       = 1
clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=2088, tv_nsec=729284951}) = 0
clock_gettime(CLOCK_PROCESS_CPUTIME_ID, {tv_sec=2088, tv_nsec=729837544}) = 0
write(1, "Chain ", 6)                   = 6
write(1, "1", 1)                        = 1
write(1, ": ", 2)                       = 2
write(1, "1\n", 2)                      = 2
write(1, "\n", 1)                       = 1
write(1, "Chain ", 6)                   = 6
write(1, "1", 1)                        = 1
write(1, ": ", 2)                       = 2
write(1, "Initial log joint probability = "..., 41) = 41
write(1, "\n", 1)                       = 1
getrusage(RUSAGE_SELF, {ru_utime={tv_sec=2018, tv_usec=768000}, ru_stime={tv_sec=69, tv_usec=964000}, ...}) = 0
getrusage(RUSAGE_CHILDREN, {ru_utime={tv_sec=40, tv_usec=860000}, ru_stime={tv_sec=1, tv_usec=244000}, ...}) = 0
write(1, "Chain ", 6)                   = 6
write(1, "1", 1)                        = 1
write(1, ": ", 2)                       = 2
write(1, "    Iter      log prob        ||"..., 91) = 91
write(1, "\n", 1)                       = 1
getrusage(RUSAGE_SELF, {ru_utime={tv_sec=2018, tv_usec=768000}, ru_stime={tv_sec=69, tv_usec=964000}, ...}) = 0
getrusage(RUSAGE_CHILDREN, {ru_utime={tv_sec=40, tv_usec=860000}, ru_stime={tv_sec=1, tv_usec=244000}, ...}) = 0
write(1, "Chain ", 6)                   = 6
write(1, "1", 1)                        = 1
write(1, ": ", 2)                       = 2
write(1, "1\n1\n1\n1\n1\n1\n1\n", 14)   = 14
write(1, "\n", 1)                       = 1
getrusage(RUSAGE_SELF, {ru_utime={tv_sec=2018, tv_usec=768000}, ru_stime={tv_sec=69, tv_usec=964000}, ...}) = 0
getrusage(RUSAGE_CHILDREN, {ru_utime={tv_sec=40, tv_usec=860000}, ru_stime={tv_sec=1, tv_usec=244000}, ...}) = 0

It seems that the program stopped after calling getrusage.

Thanks for your help!

RStan Version:

2.18.2

R Version:

R version 3.6.0 (2019-04-26)

Rcpp Version:

1.0.1

Operating System:

Debian GNU/Linux 9 (stretch)

Contributor guide

No contributing guide indexed for this repository

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

Start by reproducing the sequential workload described in the issue: sampling a Stan model, building lst, and calling optimizing three times repeatedly. Compare the final optimizing output with the reported getrusage trace; done means the repeated calls return and execution continues without hanging.

Written by the indexing model from the issue text.

Assessment

Tech stack
r
Domain
data
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Needs clarification
Newbie friendliness
25/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.