Installation uses pip3 to install misc and riboutils

bmmalone commented 7 years ago

This behavior was originally discovered by @tmargus in Issue #35.

The setup.py script attempts to automatically grab misc and riboutils from the respective repos and install them using "pip3 install..." (around line 204 of setup.py). As @tmargus mentions in the other thread, anaconda does not create a pip3 command (only pip), so this produces very unexpected behavior. Namely, the packages are installed using whichever pip3 command is found (e.g., the system pip3).

I was attempting to avoid a requirements.txt file, but it appears the best option.

bmmalone commented 7 years ago

A related problem is that misc.bio_utils (and other subpackages of misc) were only correctly pulled when it was specified as editable. This was related a problem with the package specification for misc.

bmmalone commented 7 years ago

Hi @tmargus,

I believe the installation issues are now resolved, or at least closer to it. As you identified, the installation was explicitly using pip3 at one point, so that definitely wasn't playing nicely with anacodna. Additionally, as I mentioned above, there was a problem with the setup.py file for misc, so that explains why misc.bio_utils was only showing up when it was installed in editable mode.

In addition to that fix, I changed the installation to use a requirements.txt files. This ensures the correct version of pip is used the entire way through.

To test things, I tried using an anaconda virtual environment. First, it was necessary to upgrade the version of gcc used by anaconda (Issue #45).

conda install -c salford_systems libgcc-6=6.2.0
conda create -n rpbp_35 python=3.5 anaconda
source activate rpbp_35
git clone git@github.com:dieterich-lab/rp-bp.git
cd rp-bp/
git checkout dev
pip install -r requirements.txt --verbose --log log.txt

Then, things seem to be working. For example:

$ python3 -c "import misc.bio_utils; print(misc.bio_utils)"
>>> <module 'misc.bio_utils' from '/home/bmalone/install/anaconda3/envs/rpbp_35/lib/python3.5/site-packages/misc/bio_utils/__init__.py'>

Then, running the main pipeline scripts worked for me locally (within anaconda). The script names are a bit different in the dev branch, though: prepare-rpbp-genome and run-all-rpbp-instances.

prepare-rpbp-genome WBcel235.79.chrI.yaml --num-cpus 2 --mem 4G --overwrite --logging-level INFO
run-all-rpbp-instances  c-elegans-test.yaml --overwrite --num-cpus 1 --logging-level INFO --merge-replicates --flexbar-format-option format # depending on your version of flexbar, this may be necessary

Could you please try this out and let me know how it goes? Once the installation seems to be working cleanly, I will merge everything into the master branch. I really appreciate your patience.

Have a good day, Brandon

tmargus commented 7 years ago

Hi Brandon,

conda install -c salford_systems libgcc-6=6.2.0 helped solve misc library problem.

First command prepare-rpbp-genome WBcel235.79.chrI.yaml --num-cpus 2 --mem 4G --overwrite --logging-level INFO runs cleanly.

Second command run-all-rpbp-instances c-elegans-test.yaml --overwrite --num-cpus 1 --logging-level INFO --merge-replicates --flexbar-format-option format

Didn't finish. Error message:

..................................................................
INFO     root     2017-02-08 15:05:29,987 : predict-translated-orfs c-elegans-test.yaml c-elegans-test --num-cpus 1   --overwrite --file-logging-level NOTSET --logging-level INFO --stdout-logging-level NOTSET --stderr-logging-level NOTSET --merge-replicates
INFO     root     2017-02-08 15:05:29,987 : calling
WARNING  rpbp.translation_prediction.predict_translated_orfs 2017-02-08 15:05:30,653 : The --merge-replicates option was given, so --overwrite is being set to True.
INFO     riboutils.ribo_utils 2017-02-08 15:05:30,653 : Found 'riboseq_biological_replicates' key in config file
INFO     root     2017-02-08 15:05:30,822 : merge-replicate-orf-profiles /Users/tmargus/projects/rpbp/data/orf-profiles/c-elegans-rep-1.test-unique.length-29.offset-12.profiles.mtx.gz /Users/tmargus/projects/rpbp/data/orf-profiles/c-elegans-rep-2.test-unique.length-29.offset-12.profiles.mtx.gz /Users/tmargus/projects/rpbp/data/orf-profiles/c-elegans-test.test-unique.profiles.mtx.gz --file-logging-level NOTSET --stdout-logging-level NOTSET --stderr-logging-level NOTSET --logging-level INFO
INFO     root     2017-02-08 15:05:30,822 : calling
INFO     rpbp.translation_prediction.merge_replicate_orf_profiles 2017-02-08 15:05:31,413 : Reading first ORF profile
INFO     rpbp.translation_prediction.merge_replicate_orf_profiles 2017-02-08 15:05:31,424 : Adding each additional profile
INFO     rpbp.translation_prediction.merge_replicate_orf_profiles 2017-02-08 15:05:31,424 : Reading file: /Users/tmargus/projects/rpbp/data/orf-profiles/c-elegans-rep-2.test-unique.length-29.offset-12.profiles.mtx.gz
INFO     rpbp.translation_prediction.merge_replicate_orf_profiles 2017-02-08 15:05:31,439 : Writing merged profiles to disk
INFO     root     2017-02-08 15:05:31,906 : estimate-orf-bayes-factors /Users/tmargus/projects/rpbp/data/orf-profiles/c-elegans-test.test-unique.profiles.mtx.gz /Users/tmargus/projects/rpbp/data/WBcel235.79.chrI/transcript-index/WBcel235.79.chrI.genomic-orfs.atg-only.bed.gz /Users/tmargus/projects/rpbp/data/orf-predictions/c-elegans-test.test-unique.frac-0.2.rw-0.bayes-factors.bed.gz --translated-models '/Users/tmargus/Library/Application Support/rpbp/rpbp_models/translated/periodic-cauchy-mixture.pkl' '/Users/tmargus/Library/Application Support/rpbp/rpbp_models/translated/periodic-gaussian-mixture.pkl' '/Users/tmargus/Library/Application Support/rpbp/rpbp_models/translated/zero-inflated-periodic-cauchy-mixture.pkl' --untranslated-models '/Users/tmargus/Library/Application Support/rpbp/rpbp_models/untranslated/gaussian-naive-bayes.pkl' --file-logging-level NOTSET --stdout-logging-level NOTSET --stderr-logging-level NOTSET --logging-level INFO  --min-length 0 --max-length 0 --min-profile 5 --fraction 0.2 --reweighting-iterations 0 --seed 8675309 --iterations 200 --chains 2  --num-cpus 1
INFO     root     2017-02-08 15:05:31,906 : calling
INFO     rpbp.translation_prediction.estimate_orf_bayes_factors 2017-02-08 15:05:32,623 : Reading and filtering ORFs
WARNING  misc.bio 2017-02-08 15:05:32,623 : This function is deprecated. Please use the version in bio_utils.bed_utils.
INFO     rpbp.translation_prediction.estimate_orf_bayes_factors 2017-02-08 15:05:33,021 : Number of regions after filtering: 1674
WARNING: The initial buffer, adaptation window, and terminal buffer
         overflow the total number of warmup iterations.
         Defaulting to a 15%/75%/10% partition,
           init_buffer = 15
           adapt_window = 75
           term_buffer = 10

# 
#  Elapsed Time: 0.0016 seconds (Warm-up)
#                0.0015 seconds (Sampling)
#                0.0031 seconds (Total)
# 
WARNING: The initial buffer, adaptation window, and terminal buffer
         overflow the total number of warmup iterations.
         Defaulting to a 15%/75%/10% partition,
           init_buffer = 15
           adapt_window = 75
           term_buffer = 10

# 
#  Elapsed Time: 0.001382 seconds (Warm-up)
#                0.001226 seconds (Sampling)
#                0.002608 seconds (Total)
# 
WARNING: The initial buffer, adaptation window, and terminal buffer
         overflow the total number of warmup iterations.
         Defaulting to a 15%/75%/10% partition,
           init_buffer = 15
           adapt_window = 75
           term_buffer = 10

# 
#  Elapsed Time: 0.002109 seconds (Warm-up)
#                0.001708 seconds (Sampling)
#                0.003817 seconds (Total)
# 
WARNING: The initial buffer, adaptation window, and terminal buffer
         overflow the total number of warmup iterations.
         Defaulting to a 15%/75%/10% partition,
           init_buffer = 15
           adapt_window = 75
           term_buffer = 10

# 
#  Elapsed Time: 0.001939 seconds (Warm-up)
#                0.00164 seconds (Sampling)
#                0.003579 seconds (Total)
# 
WARNING: The initial buffer, adaptation window, and terminal buffer
         overflow the total number of warmup iterations.
         Defaulting to a 15%/75%/10% partition,
           init_buffer = 15
           adapt_window = 75
           term_buffer = 10

Informational Message: The current Metropolis proposal is about to be rejected because of the following issue:
Exception thrown at line 118: normal_log: Scale parameter is 0, but must be > 0!
If this warning occurs sporadically, such as for highly constrained variable types like covariance matrices, then the sampler is fine,
but if this warning occurs often then your model may be either severely ill-conditioned or misspecified.

# 
#  Elapsed Time: 0.001204 seconds (Warm-up)
#                0.000961 seconds (Sampling)
#                0.002165 seconds (Total)
# 
WARNING: The initial buffer, adaptation window, and terminal buffer
         overflow the total number of warmup iterations.
         Defaulting to a 15%/75%/10% partition,
           init_buffer = 15
           adapt_window = 75
           term_buffer = 10

# 
#  Elapsed Time: 0.001202 seconds (Warm-up)
#                0.001028 seconds (Sampling)
#                0.00223 seconds (Total)
# 
WARNING: The initial buffer, adaptation window, and terminal buffer
         overflow the total number of warmup iterations.
         Defaulting to a 15%/75%/10% partition,
           init_buffer = 15
           adapt_window = 75
           term_buffer = 10

# 
#  Elapsed Time: 0.001379 seconds (Warm-up)
#                0.001158 seconds (Sampling)
#                0.002537 seconds (Total)
# 
WARNING: The initial buffer, adaptation window, and terminal buffer
         overflow the total number of warmup iterations.
         Defaulting to a 15%/75%/10% partition,
           init_buffer = 15
           adapt_window = 75
           term_buffer = 10

# 
#  Elapsed Time: 0.001247 seconds (Warm-up)
#                0.001166 seconds (Sampling)
#                0.002413 seconds (Total)
# 
/Users/tmargus/anaconda/envs/rpbp_35/lib/python3.5/site-packages/scipy/stats/stats.py:4351: RuntimeWarning: invalid value encountered in true_divide
  terms = (f_obs - f_exp)**2 / f_exp
WARNING: The initial buffer, adaptation window, and terminal buffer
         overflow the total number of warmup iterations.
         Defaulting to a 15%/75%/10% partition,
           init_buffer = 15
           adapt_window = 75
           term_buffer = 10

# 
#  Elapsed Time: 0.003899 seconds (Warm-up)
#                0.001914 seconds (Sampling)
#                0.005813 seconds (Total)
# 
WARNING: The initial buffer, adaptation window, and terminal buffer
         overflow the total number of warmup iterations.
         Defaulting to a 15%/75%/10% partition,
           init_buffer = 15
           adapt_window = 75
           term_buffer = 10

# 
#  Elapsed Time: 0.008212 seconds (Warm-up)
#                0.001307 seconds (Sampling)
#                0.009519 seconds (Total)
# 
WARNING: The initial buffer, adaptation window, and terminal buffer
         overflow the total number of warmup iterations.
         Defaulting to a 15%/75%/10% partition,
           init_buffer = 15
           adapt_window = 75
           term_buffer = 10

Informational Message: The current Metropolis proposal is about to be rejected because of the following issue:
Exception thrown at line 76: normal_log: Scale parameter is 0, but must be > 0!
If this warning occurs sporadically, such as for highly constrained variable types like covariance matrices, then the sampler is fine,
but if this warning occurs often then your model may be either severely ill-conditioned or misspecified.

# 
#  Elapsed Time: 0.040346 seconds (Warm-up)
#                0.000796 seconds (Sampling)
#                0.041142 seconds (Total)
# 
WARNING: The initial buffer, adaptation window, and terminal buffer
         overflow the total number of warmup iterations.
         Defaulting to a 15%/75%/10% partition,
           init_buffer = 15
           adapt_window = 75
           term_buffer = 10

# 
#  Elapsed Time: 0.066505 seconds (Warm-up)
#                0.000963 seconds (Sampling)
#                0.067468 seconds (Total)
# 
multiprocessing.pool.RemoteTraceback: 
"""
Traceback (most recent call last):
  File "/Users/tmargus/anaconda/envs/rpbp_35/lib/python3.5/multiprocessing/pool.py", line 119, in worker
    result = (True, func(*args, **kwds))
  File "/Users/tmargus/anaconda/envs/rpbp_35/lib/python3.5/multiprocessing/pool.py", line 47, in starmapstar
    return list(itertools.starmap(args[0], args[1]))
  File "/Users/tmargus/anaconda/envs/rpbp_35/lib/python3.5/site-packages/rpbp/translation_prediction/estimate_orf_bayes_factors.py", line 330, in get_all_bayes_factors_args
    row_bf = get_bayes_factor(profile, translated_models, untranslated_models, args)
  File "/Users/tmargus/anaconda/envs/rpbp_35/lib/python3.5/site-packages/rpbp/translation_prediction/estimate_orf_bayes_factors.py", line 167, in get_bayes_factor
    seed=args.seed, refresh=0) for tm in translated_models]
  File "/Users/tmargus/anaconda/envs/rpbp_35/lib/python3.5/site-packages/rpbp/translation_prediction/estimate_orf_bayes_factors.py", line 167, in <listcomp>
    seed=args.seed, refresh=0) for tm in translated_models]
  File "/Users/tmargus/anaconda/envs/rpbp_35/lib/python3.5/site-packages/pystan/model.py", line 666, in sampling
    fit = self.fit_class(data)
  File "stanfit4anon_model_d04e92c4121553ed8218ca71848fedac_2622784015206635022.pyx", line 454, in stanfit4anon_model_d04e92c4121553ed8218ca71848fedac_2622784015206635022.StanFit4Model.__cinit__ (/var/folders/l4/s3q_7qdj0yd5p4t0t7kr71b00000gn/T/tmprj_46jnh/stanfit4anon_model_d04e92c4121553ed8218ca71848fedac_2622784015206635022.cpp:8745)
ValueError: Exception thrown at line 83: mean: m has size 0, but must have a non-zero size
"""

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/Users/tmargus/anaconda/envs/rpbp_35/bin/estimate-orf-bayes-factors", line 11, in <module>
    load_entry_point('rpbp==1.1', 'console_scripts', 'estimate-orf-bayes-factors')()
  File "/Users/tmargus/anaconda/envs/rpbp_35/lib/python3.5/site-packages/rpbp/translation_prediction/estimate_orf_bayes_factors.py", line 526, in main
    get_all_bayes_factors_args, num_groups=args.num_groups)
  File "/Users/tmargus/anaconda/envs/rpbp_35/lib/python3.5/site-packages/rpbp/translation_prediction/estimate_orf_bayes_factors.py", line 367, in apply_starmap_split
    res = apply_starmap_groups(split_groups, num_cpus, func, *args)
  File "/Users/tmargus/anaconda/envs/rpbp_35/lib/python3.5/site-packages/rpbp/translation_prediction/estimate_orf_bayes_factors.py", line 356, in apply_starmap_groups
    results = pool.starmap(func, starmap_args)
  File "/Users/tmargus/anaconda/envs/rpbp_35/lib/python3.5/multiprocessing/pool.py", line 268, in starmap
    return self._map_async(func, iterable, starmapstar, chunksize).get()
  File "/Users/tmargus/anaconda/envs/rpbp_35/lib/python3.5/multiprocessing/pool.py", line 608, in get
    raise self._value
ValueError: Exception thrown at line 83: mean: m has size 0, but must have a non-zero size
Traceback (most recent call last):
  File "/Users/tmargus/anaconda/envs/rpbp_35/bin/predict-translated-orfs", line 11, in <module>
    load_entry_point('rpbp==1.1', 'console_scripts', 'predict-translated-orfs')()
  File "/Users/tmargus/anaconda/envs/rpbp_35/lib/python3.5/site-packages/rpbp/translation_prediction/predict_translated_orfs.py", line 218, in main
    file_checkers=file_checkers, overwrite=args.overwrite, call=call)
  File "/Users/tmargus/anaconda/envs/rpbp_35/lib/python3.5/site-packages/misc/shell_utils.py", line 241, in call_if_not_exists
    ret_code = check_call(cmd, call=call, raise_on_error=raise_on_error)
  File "/Users/tmargus/anaconda/envs/rpbp_35/lib/python3.5/site-packages/misc/shell_utils.py", line 89, in check_call
    return check_call_step(cmd, call=call, raise_on_error=raise_on_error)
  File "/Users/tmargus/anaconda/envs/rpbp_35/lib/python3.5/site-packages/misc/shell_utils.py", line 72, in check_call_step
    raise subprocess.CalledProcessError(ret_code, cmd)
subprocess.CalledProcessError: Command 'estimate-orf-bayes-factors /Users/tmargus/projects/rpbp/data/orf-profiles/c-elegans-test.test-unique.profiles.mtx.gz /Users/tmargus/projects/rpbp/data/WBcel235.79.chrI/transcript-index/WBcel235.79.chrI.genomic-orfs.atg-only.bed.gz /Users/tmargus/projects/rpbp/data/orf-predictions/c-elegans-test.test-unique.frac-0.2.rw-0.bayes-factors.bed.gz --translated-models '/Users/tmargus/Library/Application Support/rpbp/rpbp_models/translated/periodic-cauchy-mixture.pkl' '/Users/tmargus/Library/Application Support/rpbp/rpbp_models/translated/periodic-gaussian-mixture.pkl' '/Users/tmargus/Library/Application Support/rpbp/rpbp_models/translated/zero-inflated-periodic-cauchy-mixture.pkl' --untranslated-models '/Users/tmargus/Library/Application Support/rpbp/rpbp_models/untranslated/gaussian-naive-bayes.pkl' --file-logging-level NOTSET --stdout-logging-level NOTSET --stderr-logging-level NOTSET --logging-level INFO  --min-length 0 --max-length 0 --min-profile 5 --fraction 0.2 --reweighting-iterations 0 --seed 8675309 --iterations 200 --chains 2  --num-cpus 1' returned non-zero exit status 1
Traceback (most recent call last):
  File "/Users/tmargus/anaconda/envs/rpbp_35/bin/run-all-rpbp-instances", line 11, in <module>
    load_entry_point('rpbp==1.1', 'console_scripts', 'run-all-rpbp-instances')()
  File "/Users/tmargus/anaconda/envs/rpbp_35/lib/python3.5/site-packages/rpbp/run_all_rpbp_instances.py", line 178, in main
    slurm.check_sbatch(cmd, args=args, dependencies=job_ids)
  File "/Users/tmargus/anaconda/envs/rpbp_35/lib/python3.5/site-packages/misc/slurm.py", line 182, in check_sbatch
    shell_utils.check_call(cmd, call=call)
  File "/Users/tmargus/anaconda/envs/rpbp_35/lib/python3.5/site-packages/misc/shell_utils.py", line 89, in check_call
    return check_call_step(cmd, call=call, raise_on_error=raise_on_error)
  File "/Users/tmargus/anaconda/envs/rpbp_35/lib/python3.5/site-packages/misc/shell_utils.py", line 72, in check_call_step
    raise subprocess.CalledProcessError(ret_code, cmd)
subprocess.CalledProcessError: Command 'predict-translated-orfs c-elegans-test.yaml c-elegans-test --num-cpus 1   --overwrite --file-logging-level NOTSET --logging-level INFO --stdout-logging-level NOTSET --stderr-logging-level NOTSET --merge-replicates' returned non-zero exit status 1

Cheers, Tonu

tmargus commented 7 years ago

Hi Brandon, --star-read-files-command shows up in run-all-rpbp-instances --help I didn't try it as default is gzcat. Tonu

bmmalone commented 7 years ago

Hi Tonu,

Okay, glad to hear the --star-read-files-command is now showing up and behaving as expected. However, I can't seem to reproduce the "size 0" error above. It seems likely that something is silently failing upstream. Could you please run it in debug mode, and save the entire output to a file?

run-all-rpbp-instances c-elegans-test.yaml --overwrite --num-cpus 1 --logging-level DEBUG --merge-replicates --flexbar-format-option format --log-file log.txt

Also, just to make sure the package versions are the same, could you please also upload the versions from pip freeze?

The debug output is pretty thorough, so hopefully something in the logs points to what is happening. Please let me know. Thanks.

Have a good day, Brandon

tmargus commented 7 years ago

Here is log file

DEBUG    misc.slurm 2017-02-08 17:28:21,953 : slurm.check_sbatch.use_slurm: False, call: True
INFO     root     2017-02-08 17:28:21,953 : run-rpbp-pipeline /Users/tmargus/projects/rpbp/data/c-elegans.test-chrI.rep-1.fastq.gz c-elegans-test.yaml c-elegans-rep-1 --num-cpus 4   --overwrite --logging-level DEBUG --file-logging-level NOTSET --stderr-logging-level NOTSET --stdout-logging-level NOTSET --log-file log.txt --star-executable STAR --star-read-files-command gzcat --profiles-only --flexbar-format-option format 
INFO     root     2017-02-08 17:28:21,953 : calling
DEBUG    rpbp.run_rpbp_pipeline 2017-02-08 17:28:22,278 : use_slurm: False
INFO     root     2017-02-08 17:28:22,278 : create-orf-profiles /Users/tmargus/projects/rpbp/data/c-elegans.test-chrI.rep-1.fastq.gz c-elegans-test.yaml c-elegans-rep-1 --num-cpus 4  --overwrite --log-file log.txt --file-logging-level NOTSET --logging-level DEBUG --stdout-logging-level NOTSET --stderr-logging-level NOTSET --star-read-files-command gzcat --star-executable STAR  --flexbar-format-option format 
INFO     root     2017-02-08 17:28:22,278 : calling
INFO     rpbp.orf_profile_construction.create_orf_profiles 2017-02-08 17:28:22,923 : [create-orf-profiles]: /Users/tmargus/anaconda/envs/rpbp_35/bin/create-orf-profiles /Users/tmargus/projects/rpbp/data/c-elegans.test-chrI.rep-1.fastq.gz c-elegans-test.yaml c-elegans-rep-1 --num-cpus 4 --overwrite --log-file log.txt --file-logging-level NOTSET --logging-level DEBUG --stdout-logging-level NOTSET --stderr-logging-level NOTSET --star-read-files-command gzcat --star-executable STAR --flexbar-format-option format
INFO     root     2017-02-08 17:28:22,954 : create-base-genome-profile /Users/tmargus/projects/rpbp/data/c-elegans.test-chrI.rep-1.fastq.gz c-elegans-test.yaml c-elegans-rep-1 --num-cpus 4  --overwrite --logging-level DEBUG --stdout-logging-level NOTSET --stderr-logging-level NOTSET --file-logging-level NOTSET --log-file log.txt --star-executable STAR --star-read-files-command gzcat  --flexbar-format-option format 
INFO     root     2017-02-08 17:28:22,955 : calling
INFO     rpbp.orf_profile_construction.create_base_genome_profile 2017-02-08 17:28:23,264 : [create-base-genome-profile]: /Users/tmargus/anaconda/envs/rpbp_35/bin/create-base-genome-profile /Users/tmargus/projects/rpbp/data/c-elegans.test-chrI.rep-1.fastq.gz c-elegans-test.yaml c-elegans-rep-1 --num-cpus 4 --overwrite --logging-level DEBUG --stdout-logging-level NOTSET --stderr-logging-level NOTSET --file-logging-level NOTSET --log-file log.txt --star-executable STAR --star-read-files-command gzcat --flexbar-format-option format
INFO     root     2017-02-08 17:28:23,284 : flexbar --format 'sanger' --max-uncalled 1  --adapters '/Users/tmargus/projects/rpbp/data/riboseq-adapters.fa' -n 4 --zip-output GZ -r /Users/tmargus/projects/rpbp/data/c-elegans.test-chrI.rep-1.fastq.gz -t /Users/tmargus/projects/rpbp/data/without-adapters/c-elegans-rep-1.test --pre-trim-left 0
INFO     root     2017-02-08 17:28:23,284 : calling
DEBUG    misc.shell_utils 2017-02-08 17:28:26,199 : Checking file for validity: /Users/tmargus/projects/rpbp/data/without-adapters/c-elegans-rep-1.test.fastq.gz
DEBUG    misc.bio_utils.fastx_utils 2017-02-08 17:28:26,200 : Guessing that fastx_file is a gzipped file
INFO     root     2017-02-08 17:28:26,380 : bowtie2 -p 4 --very-fast -x /Users/tmargus/projects/rpbp/data/ribosomal-index/X03680_1 -U /Users/tmargus/projects/rpbp/data/without-adapters/c-elegans-rep-1.test.fastq.gz -S /dev/null --un-gz /Users/tmargus/projects/rpbp/data/without-rrna/c-elegans-rep-1.test.fastq.gz --al-gz /Users/tmargus/projects/rpbp/data/with-rrna/c-elegans-rep-1.test.fastq.gz
INFO     root     2017-02-08 17:28:26,380 : calling
DEBUG    misc.shell_utils 2017-02-08 17:28:26,688 : Checking file for validity: /Users/tmargus/projects/rpbp/data/without-rrna/c-elegans-rep-1.test.fastq.gz
DEBUG    misc.bio_utils.fastx_utils 2017-02-08 17:28:26,689 : Guessing that fastx_file is a gzipped file
INFO     misc.shell_utils 2017-02-08 17:28:26,773 : bowtie2 -p 4 --very-fast -x /Users/tmargus/projects/rpbp/data/ribosomal-index/X03680_1 -U /Users/tmargus/projects/rpbp/data/without-adapters/c-elegans-rep-1.test.fastq.gz -S /dev/null --un-gz /Users/tmargus/projects/rpbp/data/without-rrna/c-elegans-rep-1.test.fastq.gz --al-gz /Users/tmargus/projects/rpbp/data/with-rrna/c-elegans-rep-1.test.fastq.gz
INFO     root     2017-02-08 17:28:26,775 : STAR --runThreadN 4 --readFilesCommand gzcat --genomeDir /Users/tmargus/projects/rpbp/data/WBcel235.79.chrI/STAR --sjdbGTFfile /Users/tmargus/projects/rpbp/data/WBcel235.79.chrI.gtf --readFilesIn /Users/tmargus/projects/rpbp/data/without-rrna/c-elegans-rep-1.test.fastq.gz --alignIntronMin 20 --alignIntronMax 100000 --outFilterMismatchNmax 1 --outFilterType 'BySJout' --outFilterIntronMotifs 'RemoveNoncanonicalUnannotated'  --outFilterMismatchNoverLmax 0.04 --outSAMattributes AS NH HI nM MD --outFileNamePrefix /Users/tmargus/projects/rpbp/data/without-rrna-mapping/c-elegans-rep-1.test --outSAMtype BAM SortedByCoordinate 
INFO     root     2017-02-08 17:28:26,775 : calling
DEBUG    misc.shell_utils 2017-02-08 17:28:41,912 : Checking file for validity: /Users/tmargus/projects/rpbp/data/without-rrna-mapping/c-elegans-rep-1.testAligned.sortedByCoord.out.bam
INFO     root     2017-02-08 17:28:41,912 : samtools view -h /Users/tmargus/projects/rpbp/data/without-rrna-mapping/c-elegans-rep-1.testAligned.sortedByCoord.out.bam > /dev/null
INFO     root     2017-02-08 17:28:41,912 : calling
INFO     misc.shell_utils 2017-02-08 17:28:41,972 : STAR --runThreadN 4 --readFilesCommand gzcat --genomeDir /Users/tmargus/projects/rpbp/data/WBcel235.79.chrI/STAR --sjdbGTFfile /Users/tmargus/projects/rpbp/data/WBcel235.79.chrI.gtf --readFilesIn /Users/tmargus/projects/rpbp/data/without-rrna/c-elegans-rep-1.test.fastq.gz --alignIntronMin 20 --alignIntronMax 100000 --outFilterMismatchNmax 1 --outFilterType 'BySJout' --outFilterIntronMotifs 'RemoveNoncanonicalUnannotated'  --outFilterMismatchNoverLmax 0.04 --outSAMattributes AS NH HI nM MD --outFileNamePrefix /Users/tmargus/projects/rpbp/data/without-rrna-mapping/c-elegans-rep-1.test --outSAMtype BAM SortedByCoordinate 
WARNING  root     2017-02-08 17:28:41,972 : [utils.create_symlink]: file already exists at: '/Users/tmargus/projects/rpbp/data/without-rrna-mapping/c-elegans-rep-1.test.bam'. It will be removed
INFO     root     2017-02-08 17:28:41,973 : samtools index -b /Users/tmargus/projects/rpbp/data/without-rrna-mapping/c-elegans-rep-1.test.bam
INFO     root     2017-02-08 17:28:41,973 : calling
INFO     root     2017-02-08 17:28:42,013 : remove-multimapping-reads /Users/tmargus/projects/rpbp/data/without-rrna-mapping/c-elegans-rep-1.test.bam /Users/tmargus/projects/rpbp/data/without-rrna-mapping/c-elegans-rep-1.test-unique.bam 
INFO     root     2017-02-08 17:28:42,014 : calling
DEBUG    misc.shell_utils 2017-02-08 17:28:42,582 : Checking file for validity: /Users/tmargus/projects/rpbp/data/without-rrna-mapping/c-elegans-rep-1.test-unique.bam
INFO     root     2017-02-08 17:28:42,582 : samtools view -h /Users/tmargus/projects/rpbp/data/without-rrna-mapping/c-elegans-rep-1.test-unique.bam > /dev/null
INFO     root     2017-02-08 17:28:42,582 : calling
INFO     misc.shell_utils 2017-02-08 17:28:42,609 : remove-multimapping-reads /Users/tmargus/projects/rpbp/data/without-rrna-mapping/c-elegans-rep-1.test.bam /Users/tmargus/projects/rpbp/data/without-rrna-mapping/c-elegans-rep-1.test-unique.bam 
INFO     root     2017-02-08 17:28:42,647 : extract-metagene-profiles /Users/tmargus/projects/rpbp/data/without-rrna-mapping/c-elegans-rep-1.test-unique.bam /Users/tmargus/projects/rpbp/data/WBcel235.79.chrI/WBcel235.79.chrI.annotated.bed.gz /Users/tmargus/projects/rpbp/data/metagene-profiles/c-elegans-rep-1.test-unique.metagene-profile.csv.gz --num-cpus 4 --logging-level DEBUG --stdout-logging-level NOTSET --stderr-logging-level NOTSET --file-logging-level NOTSET --log-file log.txt  --start-upstream 50 --start-downstream 20 --end-upstream 50 --end-downstream 20
INFO     root     2017-02-08 17:28:42,647 : calling
INFO     riboutils.extract_metagene_profiles 2017-02-08 17:28:43,277 : [extract-metagene-profiles]: /Users/tmargus/anaconda/envs/rpbp_35/bin/extract-metagene-profiles /Users/tmargus/projects/rpbp/data/without-rrna-mapping/c-elegans-rep-1.test-unique.bam /Users/tmargus/projects/rpbp/data/WBcel235.79.chrI/WBcel235.79.chrI.annotated.bed.gz /Users/tmargus/projects/rpbp/data/metagene-profiles/c-elegans-rep-1.test-unique.metagene-profile.csv.gz --num-cpus 4 --logging-level DEBUG --stdout-logging-level NOTSET --stderr-logging-level NOTSET --file-logging-level NOTSET --log-file log.txt --start-upstream 50 --start-downstream 20 --end-upstream 50 --end-downstream 20
DEBUG    riboutils.extract_metagene_profiles 2017-02-08 17:28:43,298 : Counting the number of alignments
DEBUG    riboutils.extract_metagene_profiles 2017-02-08 17:28:43,317 : Extracting 5' ends of reads from alignments
DEBUG    riboutils.extract_metagene_profiles 2017-02-08 17:28:43,357 : Constructing data frame with 5' ends of reads from alignments
INFO     riboutils.extract_metagene_profiles 2017-02-08 17:28:43,374 : Reading annotations
INFO     riboutils.extract_metagene_profiles 2017-02-08 17:28:43,400 : Constructing canonical translation initiation ORF data frames
INFO     riboutils.extract_metagene_profiles 2017-02-08 17:28:43,414 : Constructing canonical translation termination ORF data frames
INFO     riboutils.extract_metagene_profiles 2017-02-08 17:28:43,432 : Finding translation initiation site matches
DEBUG    misc.bio_utils.bed_utils 2017-02-08 17:28:43,433 : Finding matches for seqname: I, strand: +
DEBUG    misc.bio_utils.bed_utils 2017-02-08 17:28:43,451 : Finding matches for seqname: I, strand: -
DEBUG    riboutils.extract_metagene_profiles 2017-02-08 17:28:43,462 : Initiation keys: (23, '-'),(24, '+'),(34, '+'),(29, '+'),(31, '+'),(32, '+'),(25, '-'),(27, '+'),(33, '-'),(18, '+'),(20, '+'),(30, '-'),(26, '-'),(28, '+'),(21, '-'),(24, '-'),(34, '-'),(19, '-'),(29, '-'),(31, '-'),(32, '-'),(25, '+'),(27, '-'),(22, '-'),(33, '+'),(20, '-'),(30, '+'),(16, '-'),(26, '+'),(28, '-'),(21, '+')
INFO     riboutils.extract_metagene_profiles 2017-02-08 17:28:43,462 : Finding translation termination site matches
DEBUG    misc.bio_utils.bed_utils 2017-02-08 17:28:43,463 : Finding matches for seqname: I, strand: +
DEBUG    misc.bio_utils.bed_utils 2017-02-08 17:28:43,487 : Finding matches for seqname: I, strand: -
DEBUG    riboutils.extract_metagene_profiles 2017-02-08 17:28:43,500 : Termination keys: (23, '-'),(24, '+'),(25, '+'),(34, '-'),(33, '-'),(29, '-'),(31, '+'),(32, '+'),(29, '+'),(27, '+'),(27, '-'),(30, '+'),(33, '+'),(28, '-'),(31, '-'),(30, '-'),(24, '-'),(32, '-'),(28, '+')
INFO     riboutils.extract_metagene_profiles 2017-02-08 17:28:43,500 : Extracting metagene profiles
INFO     riboutils.extract_metagene_profiles 2017-02-08 17:28:43,501 : Profiles will be created for lengths: 12,13,14,15,16,17,18,19,20,21,22,23,24,25,26,27,28,29,30,31,32,33,34,35,36,37,38,40,41,42,46,48
INFO     riboutils.extract_metagene_profiles 2017-02-08 17:28:43,554 : Writing metagene profiles to disk
DEBUG    misc.utils 2017-02-08 17:28:43,554 : Attempting to guess the extension. Filename: /Users/tmargus/projects/rpbp/data/metagene-profiles/c-elegans-rep-1.test-unique.metagene-profile.csv.gz
DEBUG    misc.utils 2017-02-08 17:28:43,554 : The guessed filetype was: csv
DEBUG    misc.shell_utils 2017-02-08 17:28:43,648 : Checking file for validity: /Users/tmargus/projects/rpbp/data/metagene-profiles/c-elegans-rep-1.test-unique.metagene-profile.csv.gz
INFO     root     2017-02-08 17:28:43,649 : gunzip -t /Users/tmargus/projects/rpbp/data/metagene-profiles/c-elegans-rep-1.test-unique.metagene-profile.csv.gz
INFO     root     2017-02-08 17:28:43,649 : calling
INFO     root     2017-02-08 17:28:43,655 : estimate-metagene-profile-bayes-factors /Users/tmargus/projects/rpbp/data/metagene-profiles/c-elegans-rep-1.test-unique.metagene-profile.csv.gz /Users/tmargus/projects/rpbp/data/metagene-profiles/c-elegans-rep-1.test-unique.metagene-periodicity-bayes-factors.csv.gz --num-cpus 4 --periodic-models '/Users/tmargus/Library/Application Support/rpbp/rpbp_models/periodic/start-high-low-low.pkl' --nonperiodic-models '/Users/tmargus/Library/Application Support/rpbp/rpbp_models/nonperiodic/no-periodicity.pkl' '/Users/tmargus/Library/Application Support/rpbp/rpbp_models/nonperiodic/start-high-high-low.pkl' '/Users/tmargus/Library/Application Support/rpbp/rpbp_models/nonperiodic/start-high-low-high.pkl' --periodic-offset-start -20 --periodic-offset-end 0 --metagene-profile-length 21 --seed 8675309 --chains 2 --iterations 500 --logging-level DEBUG --stdout-logging-level NOTSET --stderr-logging-level NOTSET --file-logging-level NOTSET --log-file log.txt
INFO     root     2017-02-08 17:28:43,655 : calling
INFO     riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:44,267 : Estimating Bayes factors for lengths: 16,18,19,20,21,22,23,24,25,26,27,28,29,30,31,32,33,34
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:45,067 : Length: 20, Offset: -20
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:45,079 : Length: 18, Offset: -20
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:45,083 : Length: 19, Offset: -20
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:45,085 : Length: 16, Offset: -20
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:45,334 : Length: 20, Offset: -19
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:45,990 : Length: 20, Offset: -18
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:46,040 : Length: 18, Offset: -19
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:46,084 : Length: 16, Offset: -19
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:46,518 : Length: 19, Offset: -19
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:46,791 : Length: 20, Offset: -17
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:46,978 : Length: 18, Offset: -18
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:47,085 : Length: 16, Offset: -18
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:47,263 : Length: 20, Offset: -16
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:47,561 : Length: 20, Offset: -15
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:47,826 : Length: 20, Offset: -14
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:47,853 : Length: 19, Offset: -18
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:47,919 : Length: 18, Offset: -17
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:48,092 : Length: 16, Offset: -17
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:48,420 : Length: 20, Offset: -13
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:48,834 : Length: 18, Offset: -16
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:48,936 : Length: 20, Offset: -12
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:49,024 : Length: 16, Offset: -16
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:49,394 : Length: 19, Offset: -17
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:49,438 : Length: 20, Offset: -11
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:49,767 : Length: 18, Offset: -15
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:49,931 : Length: 20, Offset: -10
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:49,998 : Length: 16, Offset: -15
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:50,781 : Length: 20, Offset: -9
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:50,789 : Length: 18, Offset: -14
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:50,917 : Length: 19, Offset: -16
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:51,029 : Length: 16, Offset: -14
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:51,500 : Length: 20, Offset: -8
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:51,739 : Length: 18, Offset: -13
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:52,014 : Length: 16, Offset: -13
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:52,039 : Length: 20, Offset: -7
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:52,501 : Length: 19, Offset: -15
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:52,532 : Length: 20, Offset: -6
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:52,661 : Length: 18, Offset: -12
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:52,856 : Length: 20, Offset: -5
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:52,973 : Length: 16, Offset: -12
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:53,353 : Length: 20, Offset: -4
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:53,589 : Length: 18, Offset: -11
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:53,767 : Length: 20, Offset: -3
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:53,875 : Length: 16, Offset: -11
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:53,879 : Length: 19, Offset: -14
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:54,520 : Length: 18, Offset: -10
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:54,549 : Length: 20, Offset: -2
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:54,824 : Length: 16, Offset: -10
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:55,014 : Length: 19, Offset: -13
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:55,370 : Length: 20, Offset: -1
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:55,423 : Length: 18, Offset: -9
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:55,762 : Length: 16, Offset: -9
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:56,079 : Length: 20, Offset: 0
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:56,254 : Length: 19, Offset: -12
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:56,422 : Length: 18, Offset: -8
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:56,770 : Length: 16, Offset: -8
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:56,945 : Length: 21, Offset: -20
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:57,356 : Length: 18, Offset: -7
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:57,774 : Length: 21, Offset: -19
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:57,774 : Length: 16, Offset: -7
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:57,901 : Length: 19, Offset: -11
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:58,279 : Length: 18, Offset: -6
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:58,434 : Length: 21, Offset: -18
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:58,655 : Length: 16, Offset: -6
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:59,029 : Length: 21, Offset: -17
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:59,106 : Length: 18, Offset: -5
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:59,163 : Length: 19, Offset: -10
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:59,418 : Length: 16, Offset: -5
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:59,523 : Length: 21, Offset: -16
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:28:59,857 : Length: 18, Offset: -4
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:00,046 : Length: 21, Offset: -15
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:00,181 : Length: 16, Offset: -4
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:00,511 : Length: 19, Offset: -9
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:00,560 : Length: 21, Offset: -14
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:00,595 : Length: 18, Offset: -3
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:00,945 : Length: 16, Offset: -3
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:01,105 : Length: 21, Offset: -13
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:01,371 : Length: 18, Offset: -2
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:01,722 : Length: 16, Offset: -2
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:01,892 : Length: 19, Offset: -8
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:01,930 : Length: 21, Offset: -12
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:02,466 : Length: 16, Offset: -1
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:02,497 : Length: 18, Offset: -1
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:02,674 : Length: 21, Offset: -11
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:02,887 : Length: 19, Offset: -7
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:03,117 : Length: 21, Offset: -10
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:03,214 : Length: 16, Offset: 0
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:03,646 : Length: 21, Offset: -9
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:03,676 : Length: 18, Offset: 0
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:03,806 : Length: 19, Offset: -6
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:03,963 : Length: 22, Offset: -20
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:04,067 : Length: 21, Offset: -8
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:04,629 : Length: 21, Offset: -7
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:04,694 : Length: 19, Offset: -5
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:04,744 : Length: 23, Offset: -20
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:04,965 : Length: 22, Offset: -19
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:05,088 : Length: 21, Offset: -6
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:05,539 : Length: 23, Offset: -19
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:05,596 : Length: 21, Offset: -5
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:05,817 : Length: 19, Offset: -4
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:06,131 : Length: 21, Offset: -4
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:06,214 : Length: 22, Offset: -18
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:06,895 : Length: 21, Offset: -3
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:06,970 : Length: 19, Offset: -3
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:07,095 : Length: 23, Offset: -18
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:07,610 : Length: 22, Offset: -17
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:07,790 : Length: 21, Offset: -2
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:08,057 : Length: 19, Offset: -2
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:08,476 : Length: 23, Offset: -17
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:08,500 : Length: 21, Offset: -1
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:09,038 : Length: 22, Offset: -16
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:09,135 : Length: 19, Offset: -1
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:09,295 : Length: 21, Offset: 0
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:09,643 : Length: 23, Offset: -16
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:09,865 : Length: 19, Offset: 0
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:10,049 : Length: 24, Offset: -20
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:10,197 : Length: 22, Offset: -15
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:10,645 : Length: 25, Offset: -20
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:10,690 : Length: 23, Offset: -15
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:10,832 : Length: 24, Offset: -19
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:11,106 : Length: 22, Offset: -14
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:11,477 : Length: 25, Offset: -19
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:11,567 : Length: 24, Offset: -18
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:11,715 : Length: 23, Offset: -14
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:12,206 : Length: 22, Offset: -13
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:12,315 : Length: 25, Offset: -18
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:12,498 : Length: 24, Offset: -17
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:12,605 : Length: 23, Offset: -13
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:13,155 : Length: 24, Offset: -16
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:13,611 : Length: 25, Offset: -17
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:13,821 : Length: 22, Offset: -12
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:13,888 : Length: 23, Offset: -12
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:14,341 : Length: 24, Offset: -15
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:14,548 : Length: 25, Offset: -16
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:15,007 : Length: 23, Offset: -11
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:15,109 : Length: 24, Offset: -14
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:15,254 : Length: 22, Offset: -11
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:15,914 : Length: 25, Offset: -15
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:15,927 : Length: 23, Offset: -10
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:16,591 : Length: 24, Offset: -13
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:16,860 : Length: 25, Offset: -14
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:16,910 : Length: 23, Offset: -9
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:16,926 : Length: 22, Offset: -10
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:17,534 : Length: 24, Offset: -12
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:17,731 : Length: 25, Offset: -13
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:18,039 : Length: 23, Offset: -8
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:18,609 : Length: 22, Offset: -9
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:18,902 : Length: 25, Offset: -12
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:18,904 : Length: 24, Offset: -11
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:19,371 : Length: 23, Offset: -7
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:19,717 : Length: 25, Offset: -11
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:19,899 : Length: 22, Offset: -8
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:20,543 : Length: 23, Offset: -6
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:20,559 : Length: 24, Offset: -10
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:20,805 : Length: 25, Offset: -10
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:21,179 : Length: 22, Offset: -7
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:22,052 : Length: 23, Offset: -5
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:22,304 : Length: 22, Offset: -6
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:22,333 : Length: 24, Offset: -9
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:22,349 : Length: 25, Offset: -9
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:22,737 : Length: 23, Offset: -4
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:23,594 : Length: 24, Offset: -8
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:23,643 : Length: 23, Offset: -3
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:23,728 : Length: 22, Offset: -5
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:23,809 : Length: 25, Offset: -8
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:24,571 : Length: 23, Offset: -2
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:24,788 : Length: 24, Offset: -7
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:24,966 : Length: 22, Offset: -4
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:25,374 : Length: 25, Offset: -7
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:25,501 : Length: 23, Offset: -1
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:25,938 : Length: 24, Offset: -6
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:26,093 : Length: 22, Offset: -3
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:26,430 : Length: 23, Offset: 0
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:26,505 : Length: 25, Offset: -6
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:27,285 : Length: 22, Offset: -2
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:27,341 : Length: 26, Offset: -20
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:27,350 : Length: 24, Offset: -5
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:27,658 : Length: 25, Offset: -5
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:28,231 : Length: 22, Offset: -1
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:28,572 : Length: 24, Offset: -4
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:28,832 : Length: 25, Offset: -4
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:28,939 : Length: 26, Offset: -19
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:29,166 : Length: 22, Offset: 0
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:29,583 : Length: 24, Offset: -3
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:29,620 : Length: 26, Offset: -18
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:29,628 : Length: 25, Offset: -3
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:29,923 : Length: 27, Offset: -20
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:30,142 : Length: 27, Offset: -19
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:30,234 : Length: 26, Offset: -17
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:30,352 : Length: 25, Offset: -2
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:30,511 : Length: 24, Offset: -2
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:30,627 : Length: 27, Offset: -18
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:31,046 : Length: 27, Offset: -17
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:31,118 : Length: 25, Offset: -1
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:31,253 : Length: 26, Offset: -16
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:31,288 : Length: 24, Offset: -1
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:31,403 : Length: 27, Offset: -16
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:31,740 : Length: 27, Offset: -15
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:31,845 : Length: 26, Offset: -15
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:31,909 : Length: 25, Offset: 0
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:32,056 : Length: 24, Offset: 0
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:32,212 : Length: 27, Offset: -14
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:32,648 : Length: 26, Offset: -14
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:32,678 : Length: 28, Offset: -20
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:32,719 : Length: 27, Offset: -13
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:32,837 : Length: 29, Offset: -20
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:32,891 : Length: 29, Offset: -19
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:32,947 : Length: 29, Offset: -18
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:33,000 : Length: 29, Offset: -17
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:33,001 : Length: 28, Offset: -19
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:33,055 : Length: 29, Offset: -16
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:33,066 : Length: 27, Offset: -12
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:33,109 : Length: 29, Offset: -15
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:33,161 : Length: 29, Offset: -14
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:33,213 : Length: 29, Offset: -13
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:33,267 : Length: 29, Offset: -12
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:33,321 : Length: 29, Offset: -11
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:33,375 : Length: 29, Offset: -10
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:33,432 : Length: 29, Offset: -9
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:33,465 : Length: 28, Offset: -18
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:33,495 : Length: 29, Offset: -8
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:33,523 : Length: 27, Offset: -11
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:33,557 : Length: 29, Offset: -7
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:33,580 : Length: 26, Offset: -13
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:33,639 : Length: 29, Offset: -6
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:33,742 : Length: 29, Offset: -5
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:33,822 : Length: 27, Offset: -10
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:33,974 : Length: 29, Offset: -4
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:34,011 : Length: 28, Offset: -17
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:34,078 : Length: 29, Offset: -3
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:34,114 : Length: 27, Offset: -9
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:34,161 : Length: 29, Offset: -2
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:34,240 : Length: 29, Offset: -1
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:34,301 : Length: 29, Offset: 0
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:34,304 : Length: 26, Offset: -12
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:34,360 : Length: 28, Offset: -16
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:34,501 : Length: 30, Offset: -20
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:34,551 : Length: 27, Offset: -8
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:34,562 : Length: 30, Offset: -19
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:34,622 : Length: 30, Offset: -18
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:34,639 : Length: 28, Offset: -15
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:34,679 : Length: 30, Offset: -17
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:34,741 : Length: 30, Offset: -16
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:34,797 : Length: 30, Offset: -15
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:34,827 : Length: 28, Offset: -14
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:34,852 : Length: 30, Offset: -14
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:34,911 : Length: 30, Offset: -13
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:34,968 : Length: 30, Offset: -12
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:35,022 : Length: 30, Offset: -11
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:35,081 : Length: 30, Offset: -10
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:35,119 : Length: 27, Offset: -7
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:35,128 : Length: 28, Offset: -13
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:35,137 : Length: 30, Offset: -9
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:35,166 : Length: 26, Offset: -11
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:35,191 : Length: 30, Offset: -8
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:35,253 : Length: 30, Offset: -7
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:35,308 : Length: 30, Offset: -6
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:35,362 : Length: 30, Offset: -5
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:35,420 : Length: 30, Offset: -4
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:35,475 : Length: 30, Offset: -3
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:35,523 : Length: 28, Offset: -12
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:35,531 : Length: 30, Offset: -2
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:35,587 : Length: 30, Offset: -1
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:35,642 : Length: 30, Offset: 0
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:35,724 : Length: 31, Offset: -20
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:35,780 : Length: 31, Offset: -19
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:35,795 : Length: 28, Offset: -11
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:35,835 : Length: 31, Offset: -18
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:35,893 : Length: 31, Offset: -17
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:35,915 : Length: 26, Offset: -10
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:35,954 : Length: 31, Offset: -16
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:36,011 : Length: 31, Offset: -15
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:36,069 : Length: 31, Offset: -14
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:36,129 : Length: 31, Offset: -13
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:36,186 : Length: 31, Offset: -12
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:36,241 : Length: 28, Offset: -10
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:36,247 : Length: 31, Offset: -11
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:36,304 : Length: 31, Offset: -10
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:36,351 : Length: 27, Offset: -6
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:36,360 : Length: 31, Offset: -9
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:36,417 : Length: 31, Offset: -8
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:36,480 : Length: 31, Offset: -7
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:36,545 : Length: 31, Offset: -6
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:36,607 : Length: 31, Offset: -5
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:36,663 : Length: 26, Offset: -9
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:36,666 : Length: 31, Offset: -4
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:36,686 : Length: 28, Offset: -9
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:36,738 : Length: 31, Offset: -3
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:36,800 : Length: 31, Offset: -2
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:36,858 : Length: 31, Offset: -1
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:36,917 : Length: 31, Offset: 0
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:36,998 : Length: 32, Offset: -20
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:37,078 : Length: 28, Offset: -8
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:37,327 : Length: 32, Offset: -19
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:37,432 : Length: 28, Offset: -7
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:37,457 : Length: 27, Offset: -5
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:37,544 : Length: 26, Offset: -8
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:37,751 : Length: 32, Offset: -18
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:37,752 : Length: 28, Offset: -6
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:37,935 : Length: 28, Offset: -5
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:38,126 : Length: 32, Offset: -17
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:38,217 : Length: 28, Offset: -4
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:38,225 : Length: 26, Offset: -7
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:38,352 : Length: 32, Offset: -16
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:38,641 : Length: 28, Offset: -3
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:38,645 : Length: 27, Offset: -4
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:38,940 : Length: 32, Offset: -15
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:39,073 : Length: 26, Offset: -6
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:39,237 : Length: 28, Offset: -2
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:39,497 : Length: 32, Offset: -14
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:39,567 : Length: 28, Offset: -1
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:39,770 : Length: 32, Offset: -13
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:39,784 : Length: 27, Offset: -3
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:39,984 : Length: 28, Offset: 0
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:40,001 : Length: 26, Offset: -5
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:40,339 : Length: 33, Offset: -20
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:40,553 : Length: 32, Offset: -12
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:40,704 : Length: 27, Offset: -2
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:40,739 : Length: 26, Offset: -4
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:40,845 : Length: 32, Offset: -11
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:40,943 : Length: 33, Offset: -19
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:41,471 : Length: 26, Offset: -3
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:41,623 : Length: 33, Offset: -18
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:41,675 : Length: 27, Offset: -1
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:41,689 : Length: 32, Offset: -10
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:42,095 : Length: 33, Offset: -17
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:42,197 : Length: 26, Offset: -2
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:42,320 : Length: 32, Offset: -9
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:42,661 : Length: 33, Offset: -16
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:42,912 : Length: 26, Offset: -1
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:42,916 : Length: 27, Offset: 0
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:43,200 : Length: 32, Offset: -8
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:43,201 : Length: 33, Offset: -15
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:43,693 : Length: 32, Offset: -7
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:43,718 : Length: 33, Offset: -14
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:44,015 : Length: 26, Offset: 0
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:44,061 : Length: 34, Offset: -20
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:44,325 : Length: 32, Offset: -6
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:44,343 : Length: 33, Offset: -13
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:44,795 : Length: 34, Offset: -19
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:44,884 : Length: 32, Offset: -5
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:45,207 : Length: 33, Offset: -12
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:45,464 : Length: 32, Offset: -4
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:45,544 : Length: 34, Offset: -18
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:45,687 : Length: 32, Offset: -3
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:45,837 : Length: 33, Offset: -11
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:45,858 : Length: 32, Offset: -2
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:45,924 : Length: 32, Offset: -1
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:46,002 : Length: 32, Offset: 0
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:46,277 : Length: 34, Offset: -17
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:46,447 : Length: 33, Offset: -10
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:46,864 : Length: 33, Offset: -9
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:47,001 : Length: 34, Offset: -16
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:47,637 : Length: 33, Offset: -8
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:47,729 : Length: 34, Offset: -15
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:48,319 : Length: 33, Offset: -7
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:48,452 : Length: 34, Offset: -14
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:49,157 : Length: 33, Offset: -6
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:49,175 : Length: 34, Offset: -13
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:49,954 : Length: 33, Offset: -5
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:49,969 : Length: 34, Offset: -12
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:50,687 : Length: 34, Offset: -11
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:50,846 : Length: 33, Offset: -4
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:51,418 : Length: 34, Offset: -10
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:51,531 : Length: 33, Offset: -3
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:52,151 : Length: 34, Offset: -9
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:52,382 : Length: 33, Offset: -2
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:52,886 : Length: 34, Offset: -8
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:53,693 : Length: 33, Offset: -1
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:53,980 : Length: 34, Offset: -7
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:54,085 : Length: 33, Offset: 0
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:55,142 : Length: 34, Offset: -6
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:56,206 : Length: 34, Offset: -5
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:57,222 : Length: 34, Offset: -4
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:57,910 : Length: 34, Offset: -3
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:58,504 : Length: 34, Offset: -2
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:29:59,390 : Length: 34, Offset: -1
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:00,661 : Length: 34, Offset: 0
INFO     riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:01,602 : Combining estimates into one data frame
DEBUG    misc.utils 2017-02-08 17:30:01,605 : Attempting to guess the extension. Filename: /Users/tmargus/projects/rpbp/data/metagene-profiles/c-elegans-rep-1.test-unique.metagene-periodicity-bayes-factors.csv.gz
DEBUG    misc.utils 2017-02-08 17:30:01,606 : The guessed filetype was: csv
DEBUG    misc.shell_utils 2017-02-08 17:30:01,681 : Checking file for validity: /Users/tmargus/projects/rpbp/data/metagene-profiles/c-elegans-rep-1.test-unique.metagene-periodicity-bayes-factors.csv.gz
INFO     root     2017-02-08 17:30:01,681 : gunzip -t /Users/tmargus/projects/rpbp/data/metagene-profiles/c-elegans-rep-1.test-unique.metagene-periodicity-bayes-factors.csv.gz
INFO     root     2017-02-08 17:30:01,682 : calling
INFO     root     2017-02-08 17:30:01,686 : select-periodic-offsets /Users/tmargus/projects/rpbp/data/metagene-profiles/c-elegans-rep-1.test-unique.metagene-periodicity-bayes-factors.csv.gz /Users/tmargus/projects/rpbp/data/metagene-profiles/c-elegans-rep-1.test-unique.periodic-offsets.csv.gz
INFO     root     2017-02-08 17:30:01,686 : calling
DEBUG    misc.shell_utils 2017-02-08 17:30:02,374 : Checking file for validity: /Users/tmargus/projects/rpbp/data/metagene-profiles/c-elegans-rep-1.test-unique.periodic-offsets.csv.gz
INFO     root     2017-02-08 17:30:02,375 : gunzip -t /Users/tmargus/projects/rpbp/data/metagene-profiles/c-elegans-rep-1.test-unique.periodic-offsets.csv.gz
INFO     root     2017-02-08 17:30:02,375 : calling
DEBUG    riboutils.ribo_utils 2017-02-08 17:30:02,530 : Num nans: 0, num predictions: 18
DEBUG    riboutils.ribo_utils 2017-02-08 17:30:02,530 : Using the likelihood filter. min_mean: 5, min_likelihood: 0.5
DEBUG    riboutils.ribo_utils 2017-02-08 17:30:02,530 : Maximum likelihood: 0.9721289791359313
INFO     root     2017-02-08 17:30:02,532 : extract-orf-profiles /Users/tmargus/projects/rpbp/data/without-rrna-mapping/c-elegans-rep-1.test-unique.bam /Users/tmargus/projects/rpbp/data/WBcel235.79.chrI/transcript-index/WBcel235.79.chrI.genomic-orfs.atg-only.bed.gz /Users/tmargus/projects/rpbp/data/WBcel235.79.chrI/transcript-index/WBcel235.79.chrI.orfs-exons.atg-only.bed.gz /Users/tmargus/projects/rpbp/data/orf-profiles/c-elegans-rep-1.test-unique.length-29.offset-12.profiles.mtx.gz --lengths 29 --offsets 12 --logging-level DEBUG --stdout-logging-level NOTSET --stderr-logging-level NOTSET --file-logging-level NOTSET --log-file log.txt  --num-cpus 4 
INFO     root     2017-02-08 17:30:02,532 : calling
INFO     rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:03,320 : [extract-orf-profiles]: /Users/tmargus/anaconda/envs/rpbp_35/bin/extract-orf-profiles /Users/tmargus/projects/rpbp/data/without-rrna-mapping/c-elegans-rep-1.test-unique.bam /Users/tmargus/projects/rpbp/data/WBcel235.79.chrI/transcript-index/WBcel235.79.chrI.genomic-orfs.atg-only.bed.gz /Users/tmargus/projects/rpbp/data/WBcel235.79.chrI/transcript-index/WBcel235.79.chrI.orfs-exons.atg-only.bed.gz /Users/tmargus/projects/rpbp/data/orf-profiles/c-elegans-rep-1.test-unique.length-29.offset-12.profiles.mtx.gz --lengths 29 --offsets 12 --logging-level DEBUG --stdout-logging-level NOTSET --stderr-logging-level NOTSET --file-logging-level NOTSET --log-file log.txt --num-cpus 4
INFO     rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:03,320 : Finding P-sites
INFO     riboutils.ribo_utils 2017-02-08 17:30:03,333 : Reading BAM file
INFO     riboutils.ribo_utils 2017-02-08 17:30:03,347 : Processing alignments
INFO     riboutils.ribo_utils 2017-02-08 17:30:03,383 : Filtering reads by length
INFO     riboutils.ribo_utils 2017-02-08 17:30:03,385 : Updating coordinates based on offsets
INFO     riboutils.ribo_utils 2017-02-08 17:30:03,405 : Discarding 3' end of reads
INFO     riboutils.ribo_utils 2017-02-08 17:30:03,407 : Sorting reads by coordinates
INFO     rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:03,409 : Reading exons
INFO     rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:03,800 : Reading ORFs
INFO     rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:04,162 : Adding the ORF index to the exons
INFO     rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:04,248 : Splitting exons and P-sites
INFO     rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:04,389 : Finding all P-site intersections
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:04,432 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:04,436 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:04,440 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:04,443 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:04,611 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:04,621 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:04,625 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:04,658 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:04,755 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:04,767 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:04,779 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:04,806 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:04,936 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:04,946 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:04,951 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:04,976 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:05,095 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:05,103 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:05,109 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:05,132 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:05,237 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:05,242 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:05,266 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:05,287 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:05,417 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:05,424 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:05,436 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:05,467 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:05,571 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:05,583 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:05,587 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:05,617 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:05,739 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:05,752 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:05,762 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:05,787 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:05,925 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:05,928 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:05,932 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:05,967 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:06,083 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:06,089 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:06,093 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:06,128 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:06,237 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:06,240 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:06,241 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:06,284 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:06,506 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:06,522 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:06,530 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:06,546 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:06,675 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:06,693 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:06,694 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:06,711 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:06,845 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:06,850 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:06,855 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:06,860 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:07,030 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:07,033 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:07,035 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:07,041 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:07,197 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:07,205 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:07,212 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:07,233 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:07,365 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:07,383 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:07,387 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:07,443 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:07,543 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:07,570 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:07,576 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:07,630 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:07,708 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:07,756 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:07,775 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:07,799 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:07,900 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:07,937 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:07,971 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:07,976 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:08,099 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:08,158 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:08,194 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:08,195 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:08,307 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:08,374 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:08,406 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:08,412 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:08,490 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:08,547 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:08,597 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:08,602 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:08,710 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:08,764 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:08,863 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:08,909 : Unique sequences: ['I']
INFO     rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:09,133 : Combining the ORF profiles into one matrix
INFO     rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:09,366 : Flipping the reverse strand profiles
INFO     rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:30:16,704 : Writing the sparse matrix to disk
DEBUG    misc.slurm 2017-02-08 17:30:17,164 : slurm.check_sbatch.use_slurm: False, call: True
INFO     root     2017-02-08 17:30:17,164 : run-rpbp-pipeline /Users/tmargus/projects/rpbp/data/c-elegans.test-chrI.rep-2.fastq.gz c-elegans-test.yaml c-elegans-rep-2 --num-cpus 4   --overwrite --logging-level DEBUG --file-logging-level NOTSET --stderr-logging-level NOTSET --stdout-logging-level NOTSET --log-file log.txt --star-executable STAR --star-read-files-command gzcat --profiles-only --flexbar-format-option format 
INFO     root     2017-02-08 17:30:17,164 : calling
DEBUG    rpbp.run_rpbp_pipeline 2017-02-08 17:30:17,471 : use_slurm: False
INFO     root     2017-02-08 17:30:17,472 : create-orf-profiles /Users/tmargus/projects/rpbp/data/c-elegans.test-chrI.rep-2.fastq.gz c-elegans-test.yaml c-elegans-rep-2 --num-cpus 4  --overwrite --logging-level DEBUG --stderr-logging-level NOTSET --log-file log.txt --stdout-logging-level NOTSET --file-logging-level NOTSET --star-executable STAR --star-read-files-command gzcat  --flexbar-format-option format 
INFO     root     2017-02-08 17:30:17,472 : calling
INFO     rpbp.orf_profile_construction.create_orf_profiles 2017-02-08 17:30:18,112 : [create-orf-profiles]: /Users/tmargus/anaconda/envs/rpbp_35/bin/create-orf-profiles /Users/tmargus/projects/rpbp/data/c-elegans.test-chrI.rep-2.fastq.gz c-elegans-test.yaml c-elegans-rep-2 --num-cpus 4 --overwrite --logging-level DEBUG --stderr-logging-level NOTSET --log-file log.txt --stdout-logging-level NOTSET --file-logging-level NOTSET --star-executable STAR --star-read-files-command gzcat --flexbar-format-option format
INFO     root     2017-02-08 17:30:18,132 : create-base-genome-profile /Users/tmargus/projects/rpbp/data/c-elegans.test-chrI.rep-2.fastq.gz c-elegans-test.yaml c-elegans-rep-2 --num-cpus 4  --overwrite --logging-level DEBUG --log-file log.txt --file-logging-level NOTSET --stdout-logging-level NOTSET --stderr-logging-level NOTSET --star-executable STAR --star-read-files-command gzcat  --flexbar-format-option format 
INFO     root     2017-02-08 17:30:18,132 : calling
INFO     rpbp.orf_profile_construction.create_base_genome_profile 2017-02-08 17:30:18,438 : [create-base-genome-profile]: /Users/tmargus/anaconda/envs/rpbp_35/bin/create-base-genome-profile /Users/tmargus/projects/rpbp/data/c-elegans.test-chrI.rep-2.fastq.gz c-elegans-test.yaml c-elegans-rep-2 --num-cpus 4 --overwrite --logging-level DEBUG --log-file log.txt --file-logging-level NOTSET --stdout-logging-level NOTSET --stderr-logging-level NOTSET --star-executable STAR --star-read-files-command gzcat --flexbar-format-option format
INFO     root     2017-02-08 17:30:18,458 : flexbar --format 'sanger' --max-uncalled 1  --adapters '/Users/tmargus/projects/rpbp/data/riboseq-adapters.fa' -n 4 --zip-output GZ -r /Users/tmargus/projects/rpbp/data/c-elegans.test-chrI.rep-2.fastq.gz -t /Users/tmargus/projects/rpbp/data/without-adapters/c-elegans-rep-2.test --pre-trim-left 0
INFO     root     2017-02-08 17:30:18,459 : calling
DEBUG    misc.shell_utils 2017-02-08 17:30:21,661 : Checking file for validity: /Users/tmargus/projects/rpbp/data/without-adapters/c-elegans-rep-2.test.fastq.gz
DEBUG    misc.bio_utils.fastx_utils 2017-02-08 17:30:21,662 : Guessing that fastx_file is a gzipped file
INFO     root     2017-02-08 17:30:21,826 : bowtie2 -p 4 --very-fast -x /Users/tmargus/projects/rpbp/data/ribosomal-index/X03680_1 -U /Users/tmargus/projects/rpbp/data/without-adapters/c-elegans-rep-2.test.fastq.gz -S /dev/null --un-gz /Users/tmargus/projects/rpbp/data/without-rrna/c-elegans-rep-2.test.fastq.gz --al-gz /Users/tmargus/projects/rpbp/data/with-rrna/c-elegans-rep-2.test.fastq.gz
INFO     root     2017-02-08 17:30:21,826 : calling
DEBUG    misc.shell_utils 2017-02-08 17:30:22,095 : Checking file for validity: /Users/tmargus/projects/rpbp/data/without-rrna/c-elegans-rep-2.test.fastq.gz
DEBUG    misc.bio_utils.fastx_utils 2017-02-08 17:30:22,096 : Guessing that fastx_file is a gzipped file
INFO     misc.shell_utils 2017-02-08 17:30:22,168 : bowtie2 -p 4 --very-fast -x /Users/tmargus/projects/rpbp/data/ribosomal-index/X03680_1 -U /Users/tmargus/projects/rpbp/data/without-adapters/c-elegans-rep-2.test.fastq.gz -S /dev/null --un-gz /Users/tmargus/projects/rpbp/data/without-rrna/c-elegans-rep-2.test.fastq.gz --al-gz /Users/tmargus/projects/rpbp/data/with-rrna/c-elegans-rep-2.test.fastq.gz
INFO     root     2017-02-08 17:30:22,169 : STAR --runThreadN 4 --readFilesCommand gzcat --genomeDir /Users/tmargus/projects/rpbp/data/WBcel235.79.chrI/STAR --sjdbGTFfile /Users/tmargus/projects/rpbp/data/WBcel235.79.chrI.gtf --readFilesIn /Users/tmargus/projects/rpbp/data/without-rrna/c-elegans-rep-2.test.fastq.gz --alignIntronMin 20 --alignIntronMax 100000 --outFilterMismatchNmax 1 --outFilterType 'BySJout' --outFilterIntronMotifs 'RemoveNoncanonicalUnannotated'  --outFilterMismatchNoverLmax 0.04 --outSAMattributes AS NH HI nM MD --outFileNamePrefix /Users/tmargus/projects/rpbp/data/without-rrna-mapping/c-elegans-rep-2.test --outSAMtype BAM SortedByCoordinate 
INFO     root     2017-02-08 17:30:22,169 : calling
DEBUG    misc.shell_utils 2017-02-08 17:30:36,947 : Checking file for validity: /Users/tmargus/projects/rpbp/data/without-rrna-mapping/c-elegans-rep-2.testAligned.sortedByCoord.out.bam
INFO     root     2017-02-08 17:30:36,947 : samtools view -h /Users/tmargus/projects/rpbp/data/without-rrna-mapping/c-elegans-rep-2.testAligned.sortedByCoord.out.bam > /dev/null
INFO     root     2017-02-08 17:30:36,947 : calling
INFO     misc.shell_utils 2017-02-08 17:30:36,993 : STAR --runThreadN 4 --readFilesCommand gzcat --genomeDir /Users/tmargus/projects/rpbp/data/WBcel235.79.chrI/STAR --sjdbGTFfile /Users/tmargus/projects/rpbp/data/WBcel235.79.chrI.gtf --readFilesIn /Users/tmargus/projects/rpbp/data/without-rrna/c-elegans-rep-2.test.fastq.gz --alignIntronMin 20 --alignIntronMax 100000 --outFilterMismatchNmax 1 --outFilterType 'BySJout' --outFilterIntronMotifs 'RemoveNoncanonicalUnannotated'  --outFilterMismatchNoverLmax 0.04 --outSAMattributes AS NH HI nM MD --outFileNamePrefix /Users/tmargus/projects/rpbp/data/without-rrna-mapping/c-elegans-rep-2.test --outSAMtype BAM SortedByCoordinate 
WARNING  root     2017-02-08 17:30:36,994 : [utils.create_symlink]: file already exists at: '/Users/tmargus/projects/rpbp/data/without-rrna-mapping/c-elegans-rep-2.test.bam'. It will be removed
INFO     root     2017-02-08 17:30:36,994 : samtools index -b /Users/tmargus/projects/rpbp/data/without-rrna-mapping/c-elegans-rep-2.test.bam
INFO     root     2017-02-08 17:30:36,994 : calling
INFO     root     2017-02-08 17:30:37,022 : remove-multimapping-reads /Users/tmargus/projects/rpbp/data/without-rrna-mapping/c-elegans-rep-2.test.bam /Users/tmargus/projects/rpbp/data/without-rrna-mapping/c-elegans-rep-2.test-unique.bam 
INFO     root     2017-02-08 17:30:37,022 : calling
DEBUG    misc.shell_utils 2017-02-08 17:30:37,563 : Checking file for validity: /Users/tmargus/projects/rpbp/data/without-rrna-mapping/c-elegans-rep-2.test-unique.bam
INFO     root     2017-02-08 17:30:37,563 : samtools view -h /Users/tmargus/projects/rpbp/data/without-rrna-mapping/c-elegans-rep-2.test-unique.bam > /dev/null
INFO     root     2017-02-08 17:30:37,563 : calling
INFO     misc.shell_utils 2017-02-08 17:30:37,589 : remove-multimapping-reads /Users/tmargus/projects/rpbp/data/without-rrna-mapping/c-elegans-rep-2.test.bam /Users/tmargus/projects/rpbp/data/without-rrna-mapping/c-elegans-rep-2.test-unique.bam 
INFO     root     2017-02-08 17:30:37,615 : extract-metagene-profiles /Users/tmargus/projects/rpbp/data/without-rrna-mapping/c-elegans-rep-2.test-unique.bam /Users/tmargus/projects/rpbp/data/WBcel235.79.chrI/WBcel235.79.chrI.annotated.bed.gz /Users/tmargus/projects/rpbp/data/metagene-profiles/c-elegans-rep-2.test-unique.metagene-profile.csv.gz --num-cpus 4 --logging-level DEBUG --log-file log.txt --file-logging-level NOTSET --stdout-logging-level NOTSET --stderr-logging-level NOTSET  --start-upstream 50 --start-downstream 20 --end-upstream 50 --end-downstream 20
INFO     root     2017-02-08 17:30:37,615 : calling
INFO     riboutils.extract_metagene_profiles 2017-02-08 17:30:38,230 : [extract-metagene-profiles]: /Users/tmargus/anaconda/envs/rpbp_35/bin/extract-metagene-profiles /Users/tmargus/projects/rpbp/data/without-rrna-mapping/c-elegans-rep-2.test-unique.bam /Users/tmargus/projects/rpbp/data/WBcel235.79.chrI/WBcel235.79.chrI.annotated.bed.gz /Users/tmargus/projects/rpbp/data/metagene-profiles/c-elegans-rep-2.test-unique.metagene-profile.csv.gz --num-cpus 4 --logging-level DEBUG --log-file log.txt --file-logging-level NOTSET --stdout-logging-level NOTSET --stderr-logging-level NOTSET --start-upstream 50 --start-downstream 20 --end-upstream 50 --end-downstream 20
DEBUG    riboutils.extract_metagene_profiles 2017-02-08 17:30:38,244 : Counting the number of alignments
DEBUG    riboutils.extract_metagene_profiles 2017-02-08 17:30:38,258 : Extracting 5' ends of reads from alignments
DEBUG    riboutils.extract_metagene_profiles 2017-02-08 17:30:38,296 : Constructing data frame with 5' ends of reads from alignments
INFO     riboutils.extract_metagene_profiles 2017-02-08 17:30:38,300 : Reading annotations
INFO     riboutils.extract_metagene_profiles 2017-02-08 17:30:38,318 : Constructing canonical translation initiation ORF data frames
INFO     riboutils.extract_metagene_profiles 2017-02-08 17:30:38,328 : Constructing canonical translation termination ORF data frames
INFO     riboutils.extract_metagene_profiles 2017-02-08 17:30:38,336 : Finding translation initiation site matches
DEBUG    misc.bio_utils.bed_utils 2017-02-08 17:30:38,336 : Finding matches for seqname: I, strand: +
DEBUG    misc.bio_utils.bed_utils 2017-02-08 17:30:38,351 : Finding matches for seqname: I, strand: -
DEBUG    riboutils.extract_metagene_profiles 2017-02-08 17:30:38,363 : Initiation keys: (23, '+'),(28, '+'),(31, '+'),(19, '+'),(26, '-'),(29, '-'),(18, '+'),(24, '+'),(22, '+'),(21, '+'),(27, '+'),(26, '+'),(32, '+'),(30, '+'),(29, '+'),(22, '-'),(19, '-'),(23, '-'),(25, '+'),(28, '-'),(27, '-'),(33, '+'),(24, '-'),(20, '-'),(30, '-'),(21, '-'),(18, '-'),(31, '-'),(32, '-')
INFO     riboutils.extract_metagene_profiles 2017-02-08 17:30:38,363 : Finding translation termination site matches
DEBUG    misc.bio_utils.bed_utils 2017-02-08 17:30:38,363 : Finding matches for seqname: I, strand: +
DEBUG    misc.bio_utils.bed_utils 2017-02-08 17:30:38,376 : Finding matches for seqname: I, strand: -
DEBUG    riboutils.extract_metagene_profiles 2017-02-08 17:30:38,386 : Termination keys: (25, '-'),(28, '+'),(31, '+'),(28, '-'),(26, '-'),(29, '-'),(33, '+'),(24, '+'),(27, '-'),(30, '-'),(27, '+'),(26, '+'),(32, '+'),(33, '-'),(30, '+'),(29, '+'),(19, '-'),(31, '-'),(32, '-')
INFO     riboutils.extract_metagene_profiles 2017-02-08 17:30:38,387 : Extracting metagene profiles
INFO     riboutils.extract_metagene_profiles 2017-02-08 17:30:38,387 : Profiles will be created for lengths: 14,15,16,17,18,19,20,21,22,23,24,25,26,27,28,29,30,31,32,33,34,35,36,37,38,40,43,50
INFO     riboutils.extract_metagene_profiles 2017-02-08 17:30:38,427 : Writing metagene profiles to disk
DEBUG    misc.utils 2017-02-08 17:30:38,427 : Attempting to guess the extension. Filename: /Users/tmargus/projects/rpbp/data/metagene-profiles/c-elegans-rep-2.test-unique.metagene-profile.csv.gz
DEBUG    misc.utils 2017-02-08 17:30:38,427 : The guessed filetype was: csv
DEBUG    misc.shell_utils 2017-02-08 17:30:38,499 : Checking file for validity: /Users/tmargus/projects/rpbp/data/metagene-profiles/c-elegans-rep-2.test-unique.metagene-profile.csv.gz
INFO     root     2017-02-08 17:30:38,499 : gunzip -t /Users/tmargus/projects/rpbp/data/metagene-profiles/c-elegans-rep-2.test-unique.metagene-profile.csv.gz
INFO     root     2017-02-08 17:30:38,499 : calling
INFO     root     2017-02-08 17:30:38,504 : estimate-metagene-profile-bayes-factors /Users/tmargus/projects/rpbp/data/metagene-profiles/c-elegans-rep-2.test-unique.metagene-profile.csv.gz /Users/tmargus/projects/rpbp/data/metagene-profiles/c-elegans-rep-2.test-unique.metagene-periodicity-bayes-factors.csv.gz --num-cpus 4 --periodic-models '/Users/tmargus/Library/Application Support/rpbp/rpbp_models/periodic/start-high-low-low.pkl' --nonperiodic-models '/Users/tmargus/Library/Application Support/rpbp/rpbp_models/nonperiodic/no-periodicity.pkl' '/Users/tmargus/Library/Application Support/rpbp/rpbp_models/nonperiodic/start-high-high-low.pkl' '/Users/tmargus/Library/Application Support/rpbp/rpbp_models/nonperiodic/start-high-low-high.pkl' --periodic-offset-start -20 --periodic-offset-end 0 --metagene-profile-length 21 --seed 8675309 --chains 2 --iterations 500 --logging-level DEBUG --log-file log.txt --file-logging-level NOTSET --stdout-logging-level NOTSET --stderr-logging-level NOTSET
INFO     root     2017-02-08 17:30:38,504 : calling
INFO     riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:39,148 : Estimating Bayes factors for lengths: 18,19,20,21,22,23,24,25,26,27,28,29,30,31,32,33
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:39,706 : Length: 20, Offset: -20
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:39,709 : Length: 19, Offset: -20
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:39,711 : Length: 21, Offset: -20
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:39,714 : Length: 18, Offset: -20
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:40,506 : Length: 19, Offset: -19
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:40,583 : Length: 21, Offset: -19
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:40,713 : Length: 20, Offset: -19
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:40,785 : Length: 18, Offset: -19
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:41,271 : Length: 19, Offset: -18
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:41,626 : Length: 21, Offset: -18
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:41,840 : Length: 18, Offset: -18
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:41,996 : Length: 20, Offset: -18
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:42,206 : Length: 19, Offset: -17
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:42,470 : Length: 21, Offset: -17
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:43,000 : Length: 19, Offset: -16
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:43,043 : Length: 18, Offset: -17
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:43,083 : Length: 20, Offset: -17
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:43,629 : Length: 21, Offset: -16
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:43,648 : Length: 19, Offset: -15
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:44,112 : Length: 18, Offset: -16
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:44,245 : Length: 20, Offset: -16
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:44,360 : Length: 21, Offset: -15
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:44,433 : Length: 19, Offset: -14
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:45,143 : Length: 21, Offset: -14
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:45,274 : Length: 18, Offset: -15
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:45,391 : Length: 20, Offset: -15
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:45,528 : Length: 21, Offset: -13
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:45,871 : Length: 19, Offset: -13
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:46,273 : Length: 20, Offset: -14
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:46,382 : Length: 21, Offset: -12
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:46,395 : Length: 19, Offset: -12
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:46,400 : Length: 18, Offset: -14
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:47,107 : Length: 21, Offset: -11
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:47,240 : Length: 20, Offset: -13
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:47,269 : Length: 19, Offset: -11
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:47,286 : Length: 18, Offset: -13
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:47,712 : Length: 21, Offset: -10
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:48,006 : Length: 19, Offset: -10
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:48,240 : Length: 18, Offset: -12
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:48,437 : Length: 21, Offset: -9
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:48,480 : Length: 20, Offset: -12
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:48,996 : Length: 19, Offset: -9
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:49,208 : Length: 21, Offset: -8
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:49,484 : Length: 18, Offset: -11
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:49,607 : Length: 20, Offset: -11
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:49,892 : Length: 21, Offset: -7
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:50,014 : Length: 19, Offset: -8
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:50,498 : Length: 21, Offset: -6
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:50,601 : Length: 18, Offset: -10
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:50,632 : Length: 19, Offset: -7
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:50,917 : Length: 20, Offset: -10
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:51,112 : Length: 21, Offset: -5
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:51,323 : Length: 19, Offset: -6
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:51,623 : Length: 21, Offset: -4
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:51,946 : Length: 18, Offset: -9
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:52,368 : Length: 20, Offset: -9
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:52,398 : Length: 19, Offset: -5
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:53,007 : Length: 21, Offset: -3
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:53,362 : Length: 20, Offset: -8
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:53,366 : Length: 18, Offset: -8
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:53,393 : Length: 19, Offset: -4
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:54,079 : Length: 21, Offset: -2
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:54,308 : Length: 20, Offset: -7
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:54,310 : Length: 19, Offset: -3
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:54,374 : Length: 18, Offset: -7
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:55,240 : Length: 20, Offset: -6
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:55,336 : Length: 18, Offset: -6
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:55,432 : Length: 21, Offset: -1
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:55,542 : Length: 19, Offset: -2
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:56,213 : Length: 18, Offset: -5
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:56,345 : Length: 20, Offset: -5
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:56,411 : Length: 19, Offset: -1
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:56,742 : Length: 21, Offset: 0
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:57,342 : Length: 19, Offset: 0
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:57,363 : Length: 20, Offset: -4
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:57,406 : Length: 18, Offset: -4
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:57,806 : Length: 22, Offset: -20
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:58,274 : Length: 20, Offset: -3
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:58,322 : Length: 23, Offset: -20
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:58,384 : Length: 18, Offset: -3
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:58,771 : Length: 23, Offset: -19
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:58,832 : Length: 22, Offset: -19
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:59,234 : Length: 20, Offset: -2
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:59,267 : Length: 23, Offset: -18
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:59,272 : Length: 18, Offset: -2
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:59,657 : Length: 22, Offset: -18
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:59,686 : Length: 23, Offset: -17
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:30:59,960 : Length: 20, Offset: -1
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:00,052 : Length: 23, Offset: -16
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:00,219 : Length: 22, Offset: -17
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:00,231 : Length: 18, Offset: -1
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:00,464 : Length: 23, Offset: -15
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:00,706 : Length: 20, Offset: 0
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:00,807 : Length: 22, Offset: -16
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:00,925 : Length: 23, Offset: -14
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:00,964 : Length: 18, Offset: 0
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:01,186 : Length: 22, Offset: -15
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:01,373 : Length: 23, Offset: -13
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:01,493 : Length: 24, Offset: -20
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:01,714 : Length: 23, Offset: -12
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:01,749 : Length: 22, Offset: -14
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:02,101 : Length: 25, Offset: -20
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:02,113 : Length: 23, Offset: -11
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:02,163 : Length: 24, Offset: -19
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:02,284 : Length: 22, Offset: -13
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:02,550 : Length: 23, Offset: -10
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:02,788 : Length: 22, Offset: -12
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:02,792 : Length: 25, Offset: -19
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:02,849 : Length: 24, Offset: -18
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:02,930 : Length: 23, Offset: -9
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:03,263 : Length: 22, Offset: -11
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:03,376 : Length: 25, Offset: -18
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:03,498 : Length: 23, Offset: -8
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:03,591 : Length: 22, Offset: -10
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:03,616 : Length: 24, Offset: -17
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:03,852 : Length: 23, Offset: -7
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:03,887 : Length: 22, Offset: -9
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:04,029 : Length: 25, Offset: -17
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:04,122 : Length: 23, Offset: -6
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:04,291 : Length: 22, Offset: -8
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:04,409 : Length: 24, Offset: -16
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:04,482 : Length: 23, Offset: -5
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:04,673 : Length: 22, Offset: -7
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:05,053 : Length: 25, Offset: -16
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:05,083 : Length: 22, Offset: -6
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:05,085 : Length: 23, Offset: -4
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:05,161 : Length: 24, Offset: -15
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:05,575 : Length: 22, Offset: -5
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:05,781 : Length: 23, Offset: -3
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:05,937 : Length: 25, Offset: -15
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:06,018 : Length: 22, Offset: -4
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:06,254 : Length: 22, Offset: -3
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:06,390 : Length: 24, Offset: -14
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:06,477 : Length: 23, Offset: -2
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:06,845 : Length: 25, Offset: -14
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:06,991 : Length: 22, Offset: -2
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:07,229 : Length: 24, Offset: -13
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:07,422 : Length: 25, Offset: -13
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:07,466 : Length: 23, Offset: -1
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:07,905 : Length: 22, Offset: -1
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:08,331 : Length: 23, Offset: 0
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:08,338 : Length: 25, Offset: -12
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:08,432 : Length: 24, Offset: -12
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:08,867 : Length: 22, Offset: 0
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:09,470 : Length: 24, Offset: -11
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:09,565 : Length: 26, Offset: -20
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:09,593 : Length: 25, Offset: -11
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:09,738 : Length: 27, Offset: -20
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:09,819 : Length: 27, Offset: -19
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:09,891 : Length: 27, Offset: -18
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:10,067 : Length: 26, Offset: -19
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:10,070 : Length: 27, Offset: -17
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:10,129 : Length: 24, Offset: -10
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:10,151 : Length: 27, Offset: -16
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:10,268 : Length: 27, Offset: -15
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:10,353 : Length: 27, Offset: -14
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:10,363 : Length: 26, Offset: -18
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:10,388 : Length: 25, Offset: -10
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:10,418 : Length: 27, Offset: -13
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:10,476 : Length: 27, Offset: -12
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:10,536 : Length: 27, Offset: -11
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:10,598 : Length: 27, Offset: -10
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:10,662 : Length: 27, Offset: -9
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:10,751 : Length: 27, Offset: -8
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:10,900 : Length: 26, Offset: -17
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:11,083 : Length: 24, Offset: -9
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:11,182 : Length: 27, Offset: -7
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:11,192 : Length: 26, Offset: -16
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:11,379 : Length: 25, Offset: -9
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:11,497 : Length: 27, Offset: -6
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:11,728 : Length: 26, Offset: -15
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:11,898 : Length: 27, Offset: -5
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:12,038 : Length: 26, Offset: -14
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:12,066 : Length: 24, Offset: -8
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:12,132 : Length: 25, Offset: -8
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:12,290 : Length: 26, Offset: -13
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:12,666 : Length: 27, Offset: -4
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:12,718 : Length: 24, Offset: -7
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:12,788 : Length: 26, Offset: -12
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:13,020 : Length: 27, Offset: -3
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:13,167 : Length: 26, Offset: -11
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:13,184 : Length: 25, Offset: -7
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:13,390 : Length: 27, Offset: -2
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:13,487 : Length: 24, Offset: -6
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:13,705 : Length: 26, Offset: -10
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:13,834 : Length: 27, Offset: -1
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:14,043 : Length: 24, Offset: -5
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:14,151 : Length: 27, Offset: 0
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:14,203 : Length: 26, Offset: -9
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:14,503 : Length: 25, Offset: -6
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:14,536 : Length: 26, Offset: -8
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:14,781 : Length: 28, Offset: -20
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:14,787 : Length: 24, Offset: -4
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:14,912 : Length: 26, Offset: -7
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:15,260 : Length: 28, Offset: -19
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:15,417 : Length: 26, Offset: -6
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:15,545 : Length: 24, Offset: -3
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:15,649 : Length: 28, Offset: -18
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:15,849 : Length: 25, Offset: -5
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:15,909 : Length: 28, Offset: -17
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:16,296 : Length: 24, Offset: -2
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:16,450 : Length: 28, Offset: -16
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:16,677 : Length: 26, Offset: -5
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:16,757 : Length: 28, Offset: -15
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:16,856 : Length: 25, Offset: -4
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:16,923 : Length: 28, Offset: -14
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:17,016 : Length: 28, Offset: -13
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:17,066 : Length: 24, Offset: -1
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:17,102 : Length: 28, Offset: -12
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:17,107 : Length: 26, Offset: -4
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:17,397 : Length: 28, Offset: -11
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:17,565 : Length: 26, Offset: -3
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:17,901 : Length: 28, Offset: -10
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:17,910 : Length: 25, Offset: -3
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:17,956 : Length: 24, Offset: 0
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:18,277 : Length: 28, Offset: -9
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:18,289 : Length: 26, Offset: -2
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:18,770 : Length: 28, Offset: -8
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:18,824 : Length: 29, Offset: -20
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:18,881 : Length: 29, Offset: -19
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:18,907 : Length: 25, Offset: -2
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:18,935 : Length: 29, Offset: -18
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:18,960 : Length: 28, Offset: -7
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:18,995 : Length: 29, Offset: -17
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:19,081 : Length: 29, Offset: -16
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:19,155 : Length: 29, Offset: -15
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:19,229 : Length: 29, Offset: -14
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:19,301 : Length: 29, Offset: -13
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:19,356 : Length: 29, Offset: -12
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:19,362 : Length: 28, Offset: -6
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:19,429 : Length: 29, Offset: -11
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:19,491 : Length: 26, Offset: -1
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:19,500 : Length: 29, Offset: -10
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:19,556 : Length: 29, Offset: -9
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:19,610 : Length: 29, Offset: -8
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:19,665 : Length: 29, Offset: -7
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:19,719 : Length: 29, Offset: -6
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:19,742 : Length: 28, Offset: -5
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:19,771 : Length: 29, Offset: -5
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:19,825 : Length: 29, Offset: -4
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:19,879 : Length: 29, Offset: -3
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:19,933 : Length: 29, Offset: -2
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:19,989 : Length: 29, Offset: -1
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:20,042 : Length: 29, Offset: 0
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:20,109 : Length: 30, Offset: -20
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:20,124 : Length: 25, Offset: -1
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:20,172 : Length: 30, Offset: -19
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:20,245 : Length: 30, Offset: -18
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:20,340 : Length: 30, Offset: -17
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:20,417 : Length: 30, Offset: -16
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:20,489 : Length: 30, Offset: -15
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:20,569 : Length: 30, Offset: -14
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:20,588 : Length: 28, Offset: -4
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:20,634 : Length: 30, Offset: -13
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:20,690 : Length: 30, Offset: -12
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:20,749 : Length: 30, Offset: -11
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:20,811 : Length: 30, Offset: -10
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:20,861 : Length: 26, Offset: 0
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:20,903 : Length: 30, Offset: -9
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:20,995 : Length: 30, Offset: -8
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:21,008 : Length: 28, Offset: -3
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:21,068 : Length: 30, Offset: -7
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:21,126 : Length: 30, Offset: -6
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:21,166 : Length: 28, Offset: -2
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:21,192 : Length: 30, Offset: -5
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:21,253 : Length: 30, Offset: -4
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:21,272 : Length: 25, Offset: 0
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:21,327 : Length: 30, Offset: -3
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:21,416 : Length: 30, Offset: -2
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:21,463 : Length: 28, Offset: -1
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:21,502 : Length: 30, Offset: -1
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:21,583 : Length: 30, Offset: 0
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:21,659 : Length: 31, Offset: -20
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:21,787 : Length: 28, Offset: 0
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:22,006 : Length: 31, Offset: -19
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:22,077 : Length: 32, Offset: -20
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:22,157 : Length: 33, Offset: -20
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:22,374 : Length: 31, Offset: -18
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:22,601 : Length: 32, Offset: -19
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:22,992 : Length: 31, Offset: -17
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:23,050 : Length: 32, Offset: -18
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:23,121 : Length: 31, Offset: -16
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:23,227 : Length: 31, Offset: -15
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:23,363 : Length: 31, Offset: -14
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:23,438 : Length: 31, Offset: -13
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:23,487 : Length: 32, Offset: -17
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:23,492 : Length: 33, Offset: -19
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:23,510 : Length: 31, Offset: -12
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:23,581 : Length: 31, Offset: -11
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:23,638 : Length: 31, Offset: -10
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:23,711 : Length: 31, Offset: -9
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:23,807 : Length: 31, Offset: -8
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:23,844 : Length: 32, Offset: -16
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:23,872 : Length: 31, Offset: -7
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:23,953 : Length: 31, Offset: -6
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:24,057 : Length: 31, Offset: -5
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:24,127 : Length: 31, Offset: -4
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:24,179 : Length: 32, Offset: -15
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:24,204 : Length: 31, Offset: -3
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:24,268 : Length: 31, Offset: -2
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:24,329 : Length: 31, Offset: -1
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:24,391 : Length: 31, Offset: 0
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:24,466 : Length: 33, Offset: -18
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:24,486 : Length: 32, Offset: -14
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:24,987 : Length: 32, Offset: -13
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:25,340 : Length: 32, Offset: -12
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:25,580 : Length: 33, Offset: -17
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:25,914 : Length: 32, Offset: -11
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:26,309 : Length: 32, Offset: -10
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:26,686 : Length: 32, Offset: -9
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:26,906 : Length: 33, Offset: -16
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:27,013 : Length: 32, Offset: -8
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:27,702 : Length: 32, Offset: -7
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:28,065 : Length: 33, Offset: -15
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:28,225 : Length: 32, Offset: -6
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:28,695 : Length: 32, Offset: -5
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:29,114 : Length: 32, Offset: -4
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:29,510 : Length: 33, Offset: -14
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:29,746 : Length: 32, Offset: -3
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:30,023 : Length: 32, Offset: -2
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:30,598 : Length: 32, Offset: -1
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:30,943 : Length: 32, Offset: 0
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:30,957 : Length: 33, Offset: -13
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:31,983 : Length: 33, Offset: -12
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:32,925 : Length: 33, Offset: -11
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:33,796 : Length: 33, Offset: -10
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:34,904 : Length: 33, Offset: -9
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:35,827 : Length: 33, Offset: -8
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:36,682 : Length: 33, Offset: -7
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:37,615 : Length: 33, Offset: -6
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:38,340 : Length: 33, Offset: -5
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:39,115 : Length: 33, Offset: -4
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:39,838 : Length: 33, Offset: -3
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:40,564 : Length: 33, Offset: -2
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:41,360 : Length: 33, Offset: -1
DEBUG    riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:42,100 : Length: 33, Offset: 0
INFO     riboutils.estimate_metagene_profile_bayes_factors 2017-02-08 17:31:42,990 : Combining estimates into one data frame
DEBUG    misc.utils 2017-02-08 17:31:42,994 : Attempting to guess the extension. Filename: /Users/tmargus/projects/rpbp/data/metagene-profiles/c-elegans-rep-2.test-unique.metagene-periodicity-bayes-factors.csv.gz
DEBUG    misc.utils 2017-02-08 17:31:42,994 : The guessed filetype was: csv
DEBUG    misc.shell_utils 2017-02-08 17:31:43,070 : Checking file for validity: /Users/tmargus/projects/rpbp/data/metagene-profiles/c-elegans-rep-2.test-unique.metagene-periodicity-bayes-factors.csv.gz
INFO     root     2017-02-08 17:31:43,070 : gunzip -t /Users/tmargus/projects/rpbp/data/metagene-profiles/c-elegans-rep-2.test-unique.metagene-periodicity-bayes-factors.csv.gz
INFO     root     2017-02-08 17:31:43,070 : calling
INFO     root     2017-02-08 17:31:43,074 : select-periodic-offsets /Users/tmargus/projects/rpbp/data/metagene-profiles/c-elegans-rep-2.test-unique.metagene-periodicity-bayes-factors.csv.gz /Users/tmargus/projects/rpbp/data/metagene-profiles/c-elegans-rep-2.test-unique.periodic-offsets.csv.gz
INFO     root     2017-02-08 17:31:43,075 : calling
DEBUG    misc.shell_utils 2017-02-08 17:31:43,833 : Checking file for validity: /Users/tmargus/projects/rpbp/data/metagene-profiles/c-elegans-rep-2.test-unique.periodic-offsets.csv.gz
INFO     root     2017-02-08 17:31:43,834 : gunzip -t /Users/tmargus/projects/rpbp/data/metagene-profiles/c-elegans-rep-2.test-unique.periodic-offsets.csv.gz
INFO     root     2017-02-08 17:31:43,834 : calling
DEBUG    riboutils.ribo_utils 2017-02-08 17:31:43,985 : Num nans: 0, num predictions: 16
DEBUG    riboutils.ribo_utils 2017-02-08 17:31:43,985 : Using the likelihood filter. min_mean: 5, min_likelihood: 0.5
DEBUG    riboutils.ribo_utils 2017-02-08 17:31:43,985 : Maximum likelihood: 0.9999991118094953
INFO     root     2017-02-08 17:31:43,987 : extract-orf-profiles /Users/tmargus/projects/rpbp/data/without-rrna-mapping/c-elegans-rep-2.test-unique.bam /Users/tmargus/projects/rpbp/data/WBcel235.79.chrI/transcript-index/WBcel235.79.chrI.genomic-orfs.atg-only.bed.gz /Users/tmargus/projects/rpbp/data/WBcel235.79.chrI/transcript-index/WBcel235.79.chrI.orfs-exons.atg-only.bed.gz /Users/tmargus/projects/rpbp/data/orf-profiles/c-elegans-rep-2.test-unique.length-29.offset-12.profiles.mtx.gz --lengths 29 --offsets 12 --logging-level DEBUG --log-file log.txt --file-logging-level NOTSET --stdout-logging-level NOTSET --stderr-logging-level NOTSET  --num-cpus 4 
INFO     root     2017-02-08 17:31:43,987 : calling
INFO     rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:44,758 : [extract-orf-profiles]: /Users/tmargus/anaconda/envs/rpbp_35/bin/extract-orf-profiles /Users/tmargus/projects/rpbp/data/without-rrna-mapping/c-elegans-rep-2.test-unique.bam /Users/tmargus/projects/rpbp/data/WBcel235.79.chrI/transcript-index/WBcel235.79.chrI.genomic-orfs.atg-only.bed.gz /Users/tmargus/projects/rpbp/data/WBcel235.79.chrI/transcript-index/WBcel235.79.chrI.orfs-exons.atg-only.bed.gz /Users/tmargus/projects/rpbp/data/orf-profiles/c-elegans-rep-2.test-unique.length-29.offset-12.profiles.mtx.gz --lengths 29 --offsets 12 --logging-level DEBUG --log-file log.txt --file-logging-level NOTSET --stdout-logging-level NOTSET --stderr-logging-level NOTSET --num-cpus 4
INFO     rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:44,758 : Finding P-sites
INFO     riboutils.ribo_utils 2017-02-08 17:31:44,772 : Reading BAM file
INFO     riboutils.ribo_utils 2017-02-08 17:31:44,786 : Processing alignments
INFO     riboutils.ribo_utils 2017-02-08 17:31:44,820 : Filtering reads by length
INFO     riboutils.ribo_utils 2017-02-08 17:31:44,821 : Updating coordinates based on offsets
INFO     riboutils.ribo_utils 2017-02-08 17:31:44,841 : Discarding 3' end of reads
INFO     riboutils.ribo_utils 2017-02-08 17:31:44,842 : Sorting reads by coordinates
INFO     rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:44,844 : Reading exons
INFO     rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:45,230 : Reading ORFs
INFO     rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:45,594 : Adding the ORF index to the exons
INFO     rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:45,674 : Splitting exons and P-sites
INFO     rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:45,821 : Finding all P-site intersections
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:45,865 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:45,869 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:45,873 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:45,877 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:46,052 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:46,056 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:46,064 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:46,102 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:46,205 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:46,208 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:46,227 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:46,257 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:46,382 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:46,392 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:46,409 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:46,430 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:46,548 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:46,569 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:46,583 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:46,598 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:46,699 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:46,724 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:46,737 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:46,780 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:46,879 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:46,908 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:46,914 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:46,956 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:47,028 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:47,061 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:47,065 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:47,114 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:47,192 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:47,215 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:47,226 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:47,273 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:47,364 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:47,395 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:47,396 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:47,444 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:47,519 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:47,546 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:47,557 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:47,606 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:47,660 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:47,694 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:47,697 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:47,743 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:47,861 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:47,901 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:47,909 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:47,954 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:48,003 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:48,069 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:48,080 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:48,091 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:48,157 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:48,219 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:48,236 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:48,241 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:48,319 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:48,395 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:48,405 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:48,414 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:48,491 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:48,553 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:48,567 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:48,585 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:48,680 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:48,700 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:48,737 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:48,841 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:48,854 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:48,872 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:48,930 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:49,007 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:49,030 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:49,043 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:49,082 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:49,162 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:49,175 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:49,226 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:49,233 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:49,323 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:49,331 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:49,393 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:49,408 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:49,484 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:49,487 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:49,555 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:49,560 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:49,634 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:49,666 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:49,688 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:49,734 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:49,780 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:49,849 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:49,870 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:49,995 : Unique sequences: ['I']
DEBUG    rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:50,010 : Unique sequences: ['I']
INFO     rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:50,266 : Combining the ORF profiles into one matrix
INFO     rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:50,496 : Flipping the reverse strand profiles
INFO     rpbp.orf_profile_construction.extract_orf_profiles 2017-02-08 17:31:58,102 : Writing the sparse matrix to disk
INFO     riboutils.ribo_utils 2017-02-08 17:31:58,587 : Found 'riboseq_biological_replicates' key in config file
DEBUG    misc.slurm 2017-02-08 17:31:58,588 : slurm.check_sbatch.use_slurm: False, call: True
INFO     root     2017-02-08 17:31:58,588 : predict-translated-orfs c-elegans-test.yaml c-elegans-test --num-cpus 4   --overwrite --logging-level DEBUG --file-logging-level NOTSET --stderr-logging-level NOTSET --stdout-logging-level NOTSET --log-file log.txt --merge-replicates
INFO     root     2017-02-08 17:31:58,588 : calling
DEBUG    rpbp.translation_prediction.predict_translated_orfs 2017-02-08 17:31:59,217 : [predict_translated_orfs]: /Users/tmargus/anaconda/envs/rpbp_35/bin/predict-translated-orfs c-elegans-test.yaml c-elegans-test --num-cpus 4 --overwrite --logging-level DEBUG --file-logging-level NOTSET --stderr-logging-level NOTSET --stdout-logging-level NOTSET --log-file log.txt --merge-replicates
WARNING  rpbp.translation_prediction.predict_translated_orfs 2017-02-08 17:31:59,237 : The --merge-replicates option was given, so --overwrite is being set to True.
INFO     riboutils.ribo_utils 2017-02-08 17:31:59,237 : Found 'riboseq_biological_replicates' key in config file
DEBUG    riboutils.ribo_utils 2017-02-08 17:31:59,386 : Num nans: 0, num predictions: 18
DEBUG    riboutils.ribo_utils 2017-02-08 17:31:59,387 : Using the likelihood filter. min_mean: 5, min_likelihood: 0.5
DEBUG    riboutils.ribo_utils 2017-02-08 17:31:59,387 : Maximum likelihood: 0.9721289791359313
DEBUG    riboutils.ribo_utils 2017-02-08 17:31:59,389 : Num nans: 0, num predictions: 16
DEBUG    riboutils.ribo_utils 2017-02-08 17:31:59,389 : Using the likelihood filter. min_mean: 5, min_likelihood: 0.5
DEBUG    riboutils.ribo_utils 2017-02-08 17:31:59,389 : Maximum likelihood: 0.9999991118094953
INFO     root     2017-02-08 17:31:59,390 : merge-replicate-orf-profiles /Users/tmargus/projects/rpbp/data/orf-profiles/c-elegans-rep-1.test-unique.length-29.offset-12.profiles.mtx.gz /Users/tmargus/projects/rpbp/data/orf-profiles/c-elegans-rep-2.test-unique.length-29.offset-12.profiles.mtx.gz /Users/tmargus/projects/rpbp/data/orf-profiles/c-elegans-test.test-unique.profiles.mtx.gz --stderr-logging-level NOTSET --logging-level DEBUG --file-logging-level NOTSET --log-file log.txt --stdout-logging-level NOTSET
INFO     root     2017-02-08 17:31:59,390 : calling
INFO     rpbp.translation_prediction.merge_replicate_orf_profiles 2017-02-08 17:31:59,967 : Reading first ORF profile
INFO     rpbp.translation_prediction.merge_replicate_orf_profiles 2017-02-08 17:31:59,978 : Adding each additional profile
INFO     rpbp.translation_prediction.merge_replicate_orf_profiles 2017-02-08 17:31:59,978 : Reading file: /Users/tmargus/projects/rpbp/data/orf-profiles/c-elegans-rep-2.test-unique.length-29.offset-12.profiles.mtx.gz
INFO     rpbp.translation_prediction.merge_replicate_orf_profiles 2017-02-08 17:31:59,993 : Writing merged profiles to disk
DEBUG    rpbp.translation_prediction.predict_translated_orfs 2017-02-08 17:32:00,437 : estimate-bayes-factors in_files: ['/Users/tmargus/projects/rpbp/data/orf-profiles/c-elegans-test.test-unique.profiles.mtx.gz', '/Users/tmargus/projects/rpbp/data/WBcel235.79.chrI/transcript-index/WBcel235.79.chrI.genomic-orfs.atg-only.bed.gz', "'/Users/tmargus/Library/Application Support/rpbp/rpbp_models/translated/periodic-cauchy-mixture.pkl'", "'/Users/tmargus/Library/Application Support/rpbp/rpbp_models/translated/periodic-gaussian-mixture.pkl'", "'/Users/tmargus/Library/Application Support/rpbp/rpbp_models/translated/zero-inflated-periodic-cauchy-mixture.pkl'", "'/Users/tmargus/Library/Application Support/rpbp/rpbp_models/untranslated/gaussian-naive-bayes.pkl'"]
INFO     root     2017-02-08 17:32:00,438 : estimate-orf-bayes-factors /Users/tmargus/projects/rpbp/data/orf-profiles/c-elegans-test.test-unique.profiles.mtx.gz /Users/tmargus/projects/rpbp/data/WBcel235.79.chrI/transcript-index/WBcel235.79.chrI.genomic-orfs.atg-only.bed.gz /Users/tmargus/projects/rpbp/data/orf-predictions/c-elegans-test.test-unique.frac-0.2.rw-0.bayes-factors.bed.gz --translated-models '/Users/tmargus/Library/Application Support/rpbp/rpbp_models/translated/periodic-cauchy-mixture.pkl' '/Users/tmargus/Library/Application Support/rpbp/rpbp_models/translated/periodic-gaussian-mixture.pkl' '/Users/tmargus/Library/Application Support/rpbp/rpbp_models/translated/zero-inflated-periodic-cauchy-mixture.pkl' --untranslated-models '/Users/tmargus/Library/Application Support/rpbp/rpbp_models/untranslated/gaussian-naive-bayes.pkl' --stderr-logging-level NOTSET --logging-level DEBUG --file-logging-level NOTSET --log-file log.txt --stdout-logging-level NOTSET  --min-length 0 --max-length 0 --min-profile 5 --fraction 0.2 --reweighting-iterations 0 --seed 8675309 --iterations 200 --chains 2  --num-cpus 4
INFO     root     2017-02-08 17:32:00,438 : calling
INFO     rpbp.translation_prediction.estimate_orf_bayes_factors 2017-02-08 17:32:01,146 : Reading and filtering ORFs
WARNING  misc.bio 2017-02-08 17:32:01,146 : This function is deprecated. Please use the version in bio_utils.bed_utils.
DEBUG    rpbp.translation_prediction.estimate_orf_bayes_factors 2017-02-08 17:32:01,510 : Before reading profiles. Available memory: 12070940672
INFO     rpbp.translation_prediction.estimate_orf_bayes_factors 2017-02-08 17:32:01,540 : Number of regions after filtering: 1674
DEBUG    rpbp.translation_prediction.estimate_orf_bayes_factors 2017-02-08 17:32:01,540 : Before reading models. Available memory: 12072689664
DEBUG    rpbp.translation_prediction.estimate_orf_bayes_factors 2017-02-08 17:32:01,540 : Reading models
DEBUG    rpbp.translation_prediction.estimate_orf_bayes_factors 2017-02-08 17:32:02,007 : Before parallel call. Available memory: 12048711680
DEBUG    rpbp.translation_prediction.estimate_orf_bayes_factors 2017-02-08 17:32:02,128 : After starting starmap get_all_bayes_factors. Available memory: 12018802688
DEBUG    rpbp.translation_prediction.estimate_orf_bayes_factors 2017-02-08 17:32:02,128 : After starting starmap get_all_bayes_factors. Available memory: 12018802688
DEBUG    rpbp.translation_prediction.estimate_orf_bayes_factors 2017-02-08 17:32:02,129 : Applying on regions
DEBUG    rpbp.translation_prediction.estimate_orf_bayes_factors 2017-02-08 17:32:02,129 : Applying on regions
DEBUG    rpbp.translation_prediction.estimate_orf_bayes_factors 2017-02-08 17:32:02,128 : After starting starmap get_all_bayes_factors. Available memory: 12016705536
DEBUG    rpbp.translation_prediction.estimate_orf_bayes_factors 2017-02-08 17:32:02,129 : Applying on regions
DEBUG    rpbp.translation_prediction.estimate_orf_bayes_factors 2017-02-08 17:32:02,129 : After starting starmap get_all_bayes_factors. Available memory: 12016709632
DEBUG    rpbp.translation_prediction.estimate_orf_bayes_factors 2017-02-08 17:32:02,129 : Applying on regions
DEBUG    rpbp.translation_prediction.estimate_orf_bayes_factors 2017-02-08 17:32:02,500 : After starting starmap get_all_bayes_factors. Available memory: 11915681792
DEBUG    rpbp.translation_prediction.estimate_orf_bayes_factors 2017-02-08 17:32:02,500 : Applying on regions

and pip freez ?

(rpbp_35) tmargus@:data$ pip freeze ?
alabaster==0.7.9
anaconda-client==1.6.0
anaconda-navigator==1.4.3
appdirs==1.4.0
appnope==0.1.0
appscript==1.0.1
argcomplete==1.0.0
astroid==1.4.9
astropy==1.3
Babel==2.3.4
backports.shutil-get-terminal-size==1.0.0
beautifulsoup4==4.5.3
biopython==1.68
bitarray==0.8.1
blaze==0.10.1
bokeh==0.12.4
boto==2.45.0
Bottleneck==1.2.0
cffi==1.9.1
chardet==2.3.0
chest==0.2.3
click==6.7
cloudpickle==0.2.2
clyent==1.2.2
colorama==0.3.7
configobj==5.0.6
contextlib2==0.5.4
cryptography==1.7.1
cycler==0.10.0
Cython==0.25.2
cytoolz==0.8.2
dask==0.13.0
datashape==0.5.4
decorator==4.0.11
dill==0.2.5
docopt==0.6.2
docutils==0.13.1
et-xmlfile==1.0.1
fastcache==1.0.2
Flask==0.12
Flask-Cors==3.0.2
gevent==1.2.1
graphviz==0.5.2
greenlet==0.4.11
h5py==2.6.0
HeapDict==1.0.0
idna==2.2
imagesize==0.7.1
ipykernel==4.5.2
ipython==5.1.0
ipython-genutils==0.1.0
ipywidgets==5.2.2
isort==4.2.5
itsdangerous==0.24
jdcal==1.3
jedi==0.9.0
Jinja2==2.9.4
joblib==0.10.3
jsonschema==2.5.1
jupyter==1.0.0
jupyter-client==4.4.0
jupyter-console==5.0.0
jupyter-core==4.2.1
lazy-object-proxy==1.2.2
llvmlite==0.15.0
locket==0.2.0
lxml==3.7.2
MarkupSafe==0.23
matplotlib==2.0.0
matplotlib-venn==0.11.5
misc==0.1
mistune==0.7.3
mpmath==0.19
multipledispatch==0.4.9
mygene==3.0.0
nbconvert==4.2.0
nbformat==4.2.0
networkx==1.11
nltk==3.2.2
nose==1.3.7
notebook==4.3.1
numba==0.30.1
numexpr==2.6.1
numpy==1.11.3
numpydoc==0.6.0
odo==0.5.0
openpyxl==2.4.1
pandas==0.19.2
partd==0.3.7
pathlib2==2.2.0
patsy==0.4.1
pep8==1.7.0
pexpect==4.2.1
pickleshare==0.7.4
Pillow==4.0.0
ply==3.9
prompt-toolkit==1.0.9
psutil==5.0.1
ptyprocess==0.5.1
py==1.4.32
pyasn1==0.1.9
pybedtools==0.7.9
pycosat==0.6.1
pycparser==2.17
pycrypto==2.6.1
pycurl==7.43.0
pyfasta==0.5.2
pyflakes==1.5.0
Pygments==2.1.3
pylint==1.6.4
pyOpenSSL==16.2.0
pyparsing==2.1.4
pysam==0.10.0
pystan==2.14.0.0
pytest==3.0.5
python-dateutil==2.6.0
pytz==2016.10
PyYAML==3.12
pyzmq==16.0.2
QtAwesome==0.4.3
qtconsole==4.2.1
QtPy==1.2.1
redis==2.10.5
requests==2.12.4
riboutils==0.1.1
rope-py3k==0.9.4.post1
rpbp==1.1
scikit-image==0.12.3
scikit-learn==0.18.1
scipy==0.18.1
seaborn==0.7.1
simplegeneric==0.8.1
singledispatch==3.4.0.3
six==1.10.0
snowballstemmer==1.2.1
sockjs-tornado==1.0.3
Sphinx==1.5.1
spyder==3.1.2
SQLAlchemy==1.1.5
statsmodels==0.6.1
sympy==1.0
tables==3.3.0
terminado==0.6
toolz==0.8.2
tornado==4.4.2
tqdm==4.11.2
traitlets==4.3.1
unicodecsv==0.14.1
wcwidth==0.1.7
Werkzeug==0.11.15
widgetsnbextension==1.2.6
wrapt==1.10.8
xlrd==1.0.0
XlsxWriter==0.9.6
xlwings==0.10.2
xlwt==1.2.0

Tonu

bmmalone commented 7 years ago

Hi Tonu,

Thanks; I think that does actually include the problem. Namely, several older "translated" models are still included (namely periodic-cauchy-mixture.pkl and zero-inflated-periodic-cauchy-mixture.pkl) and compiled with the master branch. Since they are still in the directory containing the models, they are included in the call to estimate-orf-bayes-factor, and I think/hope they are causing the problem.

Could you please try running just this command (with the extra models removed from the --translated-models option):

estimate-orf-bayes-factors /Users/tmargus/projects/rpbp/data/orf-profiles/c-elegans-test.test-unique.profiles.mtx.gz /Users/tmargus/projects/rpbp/data/WBcel235.79.chrI/transcript-index/WBcel235.79.chrI.genomic-orfs.atg-only.bed.gz /Users/tmargus/projects/rpbp/data/orf-predictions/c-elegans-test.test-unique.frac-0.2.rw-0.bayes-factors.bed.gz --translated-models '/Users/tmargus/Library/Application Support/rpbp/rpbp_models/translated/periodic-gaussian-mixture.pkl'  --untranslated-models '/Users/tmargus/Library/Application Support/rpbp/rpbp_models/untranslated/gaussian-naive-bayes.pkl' --stderr-logging-level NOTSET --logging-level DEBUG --file-logging-level NOTSET --log-file log.txt --stdout-logging-level NOTSET  --min-length 0 --max-length 0 --min-profile 5 --fraction 0.2 --reweighting-iterations 0 --seed 8675309 --iterations 200 --chains 2  --num-cpus 4

Either way, you can also remove the older model files:

rm '/Users/tmargus/Library/Application Support/rpbp/rpbp_models/translated/periodic-cauchy-mixture.pkl'
rm '/Users/tmargus/Library/Application Support/rpbp/rpbp_models/translated/zero-inflated-periodic-cauchy-mixture.pkl'

Please let me know how it goes. Thanks for working through this with us.

Have a good day, Brandon

tmargus commented 7 years ago

Hi Brandon,

Yes, the troublemakers were old models. Both options worked fine: the command estimate-orf-bayes-factors <long logn command> as well as removing old models and run-all-rpbp-instances c-elegans-test.yaml --overwrite --num-cpus 2 --logging-level DEBUG --merge-replicates --flexbar-format-option format --log-file log.txt finished cleanly.

Now when test is running smoothly on OSX (py3.5) I can continue with yeast data.

Cheers, Tonu

bmmalone commented 7 years ago

Hi Tonu,

Great! I will close this issue, but if anything does come up in other environments about the installation, please re-open it.

Have a good day, Brandon

dieterich-lab / rp-bp

Installation uses pip3 to install misc and riboutils #44