Expected classifier training duration

[e1mo]

I was wondering which time one should expect when it comes to training the automatic classifier.
Right now I am looking at paperless-ngx 1.10.2¹ (with 8da3ae2 applied) running in a NixOS VM with 99 correspondents (all with automatic matching), 25 tags (6 with automatic matching), 20 document types (2 with automatic matching) and 1473 Documents.
After having disabled the training queue worker prior to the 1.10 upgrade (since it would take just super long) I manually started document_create_classifier -v2 in a tmux session on the 29th. However, almost 10 days later the process is still running.
During that time, it has not finished. The process is continuously using one CPU Core (4 available) and, according to htop, sits at 5% memory (4 Gig in total, 1.6 reported as free and 3.5 as available right now). The logs report Document classification model does not exist (yet), not performing automatic matching. in regular intervals. Judging from the load graph and task results, that stems from the trainer was being started from celery and then time-out after 30 minutes.

So I am wondering if this is consistent with your experiences, could there be any other pitfalls I may not have considered, ...?

Footnotes

1. From flipping through the 1.11.x release notes, I could not find any updates to the classifier itself. Since I am not that interested in discarding ~10 Days of potential progress, I have not yet upgraded and would assume this to still be relevant to current versions. ↩

[stumpylog]

It shouldn't take more than a few minutes on a fairly normal powered machine. Certainly no where near 10 days. What is the last output from the training? What's the machine architecture?

[e1mo]

Thanks for you fast response :)

What is the last output from the training?

The manually started classifier was started with -v2, after an initial warning about nltk not being able to download the data (which I fixed), I restarted the trainer and have not seen a single line on stdout. The paperless.log shows the same output as I've seen it for the celery scheduled tasks:

[2023-01-08 10:05:00,854] [DEBUG] [paperless.classifier] Document classification model does not exist (yet), not performing automatic matching.
[2023-01-08 10:05:00,855] [DEBUG] [paperless.classifier] Gathering data from database...
[2023-01-08 10:05:29,014] [DEBUG] [paperless.classifier] 1473 documents, 6 tag(s), 93 correspondent(s), 3 document type(s). 0 storage path(es)
[2023-01-08 10:05:29,016] [DEBUG] [paperless.classifier] Vectorizing data...
[2023-01-08 10:05:32,166] [DEBUG] [paperless.classifier] Training tags classifier...
[2023-01-08 10:05:38,007] [DEBUG] [paperless.classifier] Training correspondent classifier...
[2023-01-08 11:05:00,640] [DEBUG] [paperless.classifier] Document classification model does not exist (yet), not performing automatic matching.
[2023-01-08 11:05:00,640] [DEBUG] [paperless.classifier] Gathering data from database...
[2023-01-08 11:05:29,276] [DEBUG] [paperless.classifier] 1473 documents, 6 tag(s), 93 correspondent(s), 3 document type(s). 0 storage path(es)
[2023-01-08 11:05:29,278] [DEBUG] [paperless.classifier] Vectorizing data...
[2023-01-08 11:05:32,418] [DEBUG] [paperless.classifier] Training tags classifier...
[2023-01-08 11:05:36,622] [DEBUG] [paperless.classifier] Training correspondent classifier...

journalctl -u paperless-task-queue.service shows:

Jan 08 10:05:00 helene celery[8688]: [2023-01-08 10:05:00,370] [INFO] [celery.worker.strategy] Task documents.tasks.train_classifier[1dae1b1a-45b8-4c09-97d5-b1902653d24c] received
Jan 08 10:10:00 helene celery[8688]: [2023-01-08 10:10:00,190] [INFO] [celery.worker.strategy] Task paperless_mail.tasks.process_mail_accounts[d3af95b3-36c5-457f-ba56-f277d31f9c92] received
Jan 08 10:10:01 helene celery[184335]: [2023-01-08 10:10:01,198] [INFO] [celery.app.trace] Task paperless_mail.tasks.process_mail_accounts[d3af95b3-36c5-457f-ba56-f277d31f9c92] succeeded in 0.9738653029780835s: 'No new documents were added.'
Jan 08 10:20:00 helene celery[8688]: [2023-01-08 10:20:00,356] [INFO] [celery.worker.strategy] Task paperless_mail.tasks.process_mail_accounts[150333d5-f3ee-4ccd-a6e6-4e7f9f00d3df] received
Jan 08 10:20:01 helene celery[184718]: [2023-01-08 10:20:01,845] [INFO] [celery.app.trace] Task paperless_mail.tasks.process_mail_accounts[150333d5-f3ee-4ccd-a6e6-4e7f9f00d3df] succeeded in 1.4814246019814163s: 'No new documents were added.'
Jan 08 10:30:00 helene celery[8688]: [2023-01-08 10:30:00,663] [INFO] [celery.worker.strategy] Task paperless_mail.tasks.process_mail_accounts[80eeb8b0-9d63-4cc7-b161-d849af229f1d] received
Jan 08 10:30:02 helene celery[184817]: [2023-01-08 10:30:02,013] [INFO] [celery.app.trace] Task paperless_mail.tasks.process_mail_accounts[80eeb8b0-9d63-4cc7-b161-d849af229f1d] succeeded in 1.3466675400268286s: 'No new documents were added.'
Jan 08 10:35:00 helene celery[8688]: [2023-01-08 10:35:00,744] [ERROR] [celery.worker.request] Task handler raised error: TimeLimitExceeded(1800)
Jan 08 10:35:00 helene celery[8688]: Traceback (most recent call last):
Jan 08 10:35:00 helene celery[8688]:   File "/nix/store/bpxs109sj8p0bi1icyr5gnfx6bz5y438-python3.10-billiard-4.0.0/lib/python3.10/site-packages/billiard/pool.py", line 683, in on_hard_timeout
Jan 08 10:35:00 helene celery[8688]:     raise TimeLimitExceeded(job._timeout)
Jan 08 10:35:00 helene celery[8688]: billiard.exceptions.TimeLimitExceeded: TimeLimitExceeded(1800,)
Jan 08 10:35:00 helene celery[8688]: [2023-01-08 10:35:00,750] [ERROR] [celery.worker.request] Hard time limit (1800s) exceeded for documents.tasks.train_classifier[1dae1b1a-45b8-4c09-97d5-b1902653d24c]
Jan 08 10:35:01 helene celery[8688]: [2023-01-08 10:35:01,191: ERROR/MainProcess] Process 'ForkPoolWorker-1716' pid:184622 exited with 'signal 9 (SIGKILL)'

What's the machine architecture?

x86_64 in a qemu VM, the hypervisor has the same architecture.

Edit: Just for good measure, I restart the classifier (It did not respond to ctrl+c, I had to SIGKILL the process) it with -v3 and after 10 Minutes I have not yet seen anything on stdout or stderr. paperless.log contains the same 8 lines shown in the first listing in the previous post.

[stumpylog]

That should all be fine. There's been some problems with armv7 and the classifier, but not amd64 types. And that was with tags, not correspondents. It may be something about the QEMU, perhaps scikit-learn and the libraries it uses aren't supported well by QEMU? I'm just guessing.

[e1mo]

Ah damn, forgot to get back on that. As far as I know (and I'm absolutely not an expert in this matter, very very far from it) QEMU does not impose any special limitations like these. And something is running, the load must come from somewhere.

Another thesis I came up with¹ is that scikit learn and possibly some other libraries may depend on some python compile-time optimizations. These optimizations however, are disable on NixOS² in the interest of reproducibility. Sadly I lack not only the expertise but also time and mental energy to investigate this further.

But once I have time and spoons, approaching this from the NixOS direction of things may be more sensible, even tho according to what I remember from googling around, performance penalties are expected to be in the 15% to 30% range (Citation needed), very far from the >144000% (10 days vs. 10 Minutes) I observed.

Footnotes

1. To be interpreted in the most "I don't know, just guess without any significant amount of expertise" way possible ↩

2. https://nixos.org/manual/nixpkgs/stable/#optimizations ↩

[benley]

@e1mo did you make any progress on this? I'm now encountering what I think is the same issue on NixOS.

[benley]

I've found that if I disable automatic matching for all correspondents, the training task finishes successfully. It seemingly has no issues with training tags or document types. I then re-enabled automatic matching for exactly 1 correspondent, and it still finishes normally. Next I'm going to gradually re-enable more correspondents for automatic matching and see if it's a quantity thing or if I just have a cursed correspondent or what.

[sn3ak]

Could you update us on this situation? I'm curious if you have similar results to what I've added to this thread.

[benley]

I have not figured it out yet! The problem hasn't returned, and I am still gradually enabling more automatic matchers as I use paperless-ngx. If I manage to narrow down the issue any further I will definitely post an update here.

[sn3ak]

I'm having this same issue on a FreeBSD 13.2 system. I do get two additional lines of output, included below. System has 64GB of ram with an Intel(R) Atom(TM) CPU C3758 @ 2.20GHz, running on NVME drives. I let the manual process run for 6 days before killing it. The entire time, it was using 99% of one core. At the time I only had 5 Correspondents, 6 doc types, 40 documents loaded, and only an inbox tag.

I've turned off NLTK (PAPERLESS_ENABLE_NLTK=0), enabled debug, and ran with -v3 for the manual task, all with the same result. Is there any way to get more output to see what this is chewing away at?

OMP: Warning #96: Cannot form a team with 8 threads, using 1 instead.
OMP: Hint Consider unsetting KMP_DEVICE_THREAD_LIMIT (KMP_ALL_THREADS), KMP_TEAMS_THREAD_LIMIT, and OMP_THREAD_LIMIT (if any are set).

Update:
Interestingly enough, I did as @benley did, and disabled all matching and the task completed in a few moments. enabling one automatic match also finished in a few moments. I guess I will follow the same exercise and enable a few at a time until it breaks.

Update 2:
It appears as soon as I set a 14th correspondent to Automatic things stop working correctly. Mind you I have only let it sit for 3-5 mins before SIGKILL'ing the process and trying again. I've tried 6-7 different correspondent's and they all have failed to complete. I'm going to let this sit longer and see if it get's anything done

Update3:
I turned off a few of the previously working correspondents, and enabled ones that would break. They worked just fine, so it seems I have some kind of limit to 13 automatic correspondents.

[pedrom34]

No, I meant how do you modify the environnement? With custom init scripts? By building the image yourself?

[zebrapurring]

Depends on how you start the service, since I use rc init scripts and they run /bin/sh I just added the lines above to /etc/profile.

[Atemu]

@pedrom34 they're not using Docker on Linux; they're using Jails in FreeBSD.

If you're using the regular Docker image, you shouldn't be experiencing this issue as it doesn't contain OpenMP.

[pedrom34]

@Atemu thanks, you're right, I'm on docker. But I'm experiencing the issue. The only workaround for me is to deactivate autoclassifier.

[Atemu]

Are you using the official image?

You should be able to set those env vars using docker run -e VAR=value.

[alanpearce]

I have a similar issue, running on a Hetzner ARM VM (left it nearly a week initially), but I've also tried on a Ryzen 5800X (nothing after 4 hours). For me it's certain Document Types. I suspect it might have something to do with the documents themselves, e.g. their length? Contracts is one document type that causes the process to freeze. Adding -v 3 doesn't seem to result in any additional log messages to the console nor the logfile shown in the web UI.

I don't think it's a memory issue because the Ryzen machine has 32GiB RAM, but it's running NixOS (as is the Hetzner VM), which might have some issues with its package.

[ctheune]

Just jumping in here, with a "me too". I just switched from an older Intel to an AMD 5700G system and noticed that my reboot times went through the roof and apparently that's because I'm also stuck. My numbers and log look like this:

[2023-07-17 13:05:00,639] [DEBUG] [paperless.classifier] Gathering data from database...
[2023-07-17 13:05:01,246] [DEBUG] [paperless.classifier] 422 documents, 4 tag(s), 127 correspondent(s), 14 document type(s). 0 storage path(es)
[2023-07-17 13:05:01,246] [DEBUG] [paperless.classifier] Vectorizing data...
[2023-07-17 13:05:04,671] [DEBUG] [paperless.classifier] Training tags classifier...
[2023-07-17 13:05:07,261] [DEBUG] [paperless.classifier] Training correspondent classifier...

I started the classifier manually and one thing I typically do when something is stuck is to strace it. It seems there could be some deadlock between threads going on, as I see very little going on after the log line for training the correspondent classifier is printed:

[pid  1979] write(32, "[2023-09-04 06:31:16,386] [DEBUG] [paperless.classifier] Training correspondent classifier...\n", 94) = 94
[pid  1979] close(32)                   = 0
[pid  1979] flock(31, LOCK_UN)          = 0
[pid  1979] close(31)                   = 0
[pid  1979] munmap(0x7f59b6c09000, 5582848) = 0
[pid  1979] munmap(0x7f59b66b6000, 5582848) = 0
[pid  1979] munmap(0x7f59b6163000, 5582848) = 0
[pid  1979] madvise(0x3f9a000, 6583776, MADV_HUGEPAGE) = 0
[pid  1979] madvise(0x45e2000, 6581424, MADV_HUGEPAGE) = 0
[pid  1979] madvise(0x58e0000, 6580848, MADV_HUGEPAGE) = 0
[pid  1979] brk(0x658f000)              = 0x658f000
[pid  1979] madvise(0x5f27000, 6582592, MADV_HUGEPAGE) = 0
[pid  1979] brk(0x65c0000)              = 0x65c0000
[pid  1979] brk(0x6623000)              = 0x6623000
[pid  1979] brk(0x6659000)              = 0x6659000
[pid  1979] brk(0x66d9000)              = 0x66d9000
[pid  1979] sched_yield()               = 0
[pid  1979] sched_yield()               = 0
[pid  1979] sched_yield()               = 0
[pid  1979] sched_yield()               = 0
[pid  1979] sched_yield()               = 0
[pid  1979] sched_yield()               = 0
[pid  1979] sched_yield()               = 0
[pid  1979] sched_yield()               = 0
[pid  1979] sched_yield()               = 0
[pid  1979] sched_yield()               = 0
[pid  1979] sched_yield()               = 0
[pid  1979] sched_yield()               = 0
[pid  1979] sched_yield()               = 0
[pid  1979] sched_yield()               = 0
[pid  1979] sched_yield()               = 0
[pid  1979] sched_yield()               = 0
[pid  1979] sched_yield()               = 0
[pid  1979] sched_yield()               = 0
[pid  1979] sched_yield()               = 0
[pid  1979] sched_yield()               = 0
[pid  1979] sched_yield()               = 0
[pid  1979] sched_yield()               = 0
[pid  1979] sched_yield()               = 0
[pid  1979] sched_yield()               = 0
[pid  1979] sched_yield()               = 0

The high CPU usage seems to be a spin lock in a very tight loop. I'll have a look at what's going on in Python land in the paperless code once I had some coffee.

[ctheune]

Ok, so this is interesting. It looks like a threading issue from a syscall perspective, but I'm now debugging scikit's safe_sparse_dot implementation where the second iteration in the forward pass seems to explode:

/nix/store/j138avzz2l3h5qik7z29sqc8f53n3sry-python3.10-scikit-learn-1.2.1/lib/python3.10/site-packages/sklearn/utils/extmath.py(189)safe_sparse_dot()
189  ->	        ret = a @ b

Of course this steps down into C-land. I'll try reading up on this and as someone mentioned NixOS might be compiling with sub-optimal options somehow.

[ctheune]

To compare notes. My statistics are currently:

139 correspondents
17 tags
23 document types
487 documents
2.7 million characters

[Atemu]

One major difference between the docker image and Nixpkgs is that our numpy uses OpenBLAS for libblas.so.3 by default while the docker image does not appear to use libblas at all:

Build Dependencies:
  blas:  
    detection method: pkgconfig
    found: true
    include directory: /usr/local/include
    lib directory: /usr/local/lib
    name: openblas64
    openblas configuration: USE_64BITINT=1 DYNAMIC_ARCH=1 DYNAMIC_OLDER= NO_CBLAS=
      NO_LAPACK= NO_LAPACKE= NO_AFFINITY=1 USE_OPENMP= HASWELL MAX_THREADS=2
    pc file directory: /usr/local/lib/pkgconfig
    version: 0.3.23.dev
  lapack:   
    detection method: internal
    found: true
    include directory: unknown
    lib directory: unknown
    name: dep139755841617168
    openblas configuration: unknown
    pc file directory: unknown
    version: 1.26.2
Compilers:                                                                                                 
  c:                                                                                                       
    commands: cc                                                                                                                                                                                                      
    linker: ld.bfd                                                                                                                                                                                                    
    name: gcc                                                                                              
    version: 10.2.1                                                                                        
  c++:                                                                                                     
    commands: c++                                                                                          
    linker: ld.bfd                                                                                         
    name: gcc                                                                                              
    version: 10.2.1                                                                                        
  cython:                                                                                                  
    commands: cython                                                                                       
    linker: cython                                                                                         
    name: cython                                                                                           
    version: 3.0.5                                                                                         
Machine Information:                                                                                       
  build:                                                                                                   
    cpu: x86_64                                                                                            
    endian: little                                                                                         
    family: x86_64                                                                                         
    system: linux                                                                                          
  host:                                                                                                    
    cpu: x86_64                                                                                            
    endian: little                                                                                         
    family: x86_64                                                                                         
    system: linux                                
Python Information:                                                                                        
  path: /opt/python/cp311-cp311/bin/python                                                                 
  version: '3.11'          
SIMD Extensions:                  
  baseline:                          
  - SSE                               
  - SSE2        
  - SSE3                   
  found:           
  - SSSE3
  - SSE41                      
  - POPCNT     
  - SSE42                                
  not found:                     
  - AVX             
  - F16C                                                                                                   
  - FMA3                                                                                                   
  - AVX2                                       
  - AVX512F            
  - AVX512CD
  - AVX512_KNL                
  - AVX512_KNM 
  - AVX512_SKX                
  - AVX512_CLX            
  - AVX512_CNL              
  - AVX512_ICL                     

(libblas is also not present inside the image.)

Additionally, attaching perf top reveals that nearly all of the time is spent in libblas.so.3's inner_thread.

This leads me to believe that the actual issue lies in OpenBLAS or numpy's usage thereof. For testing purposes, I'll try to build a test machine where BLAS is disabled in numpy and try to reproduce this issue.

[pedrom34]

Funny that you're suspecting numpy. I had an issue on 1.8.0 with numpy update that made my whole system (host included) unreachable.
I had a discussion with @stumpylog that led to locking numpy to an earlier version. But this workaround doesn't work anymore on v >2.0.

Here's the related issue report: #1364

[Atemu]

I'm not sure that's the same issue as I'm experiencing but I can report that, after replacing OpenBLAS with mkl using a dirty patch, classifier training happens in mere seconds as it should.

This is looking like an OpenBLAS issue though of course there is still the possibility that the cause is numpy's usage of BLAS.

[Atemu]

A culprit has been identified and workaround found in NixOS/nixpkgs#240591:

OMP_NUM_THREADS=1

Could those experiencing the issue outside of NixOS confirm whether this works for them too?

[Atemu]

Are there any representative generic scikit-learn benchmarks we could run on our respective systems to see whether this is a general issue or a paperless one?

[ryane]

Another "me too" here. My system (also nixos) is hanging at the tags classifier, and bizarrely enough, similar to @sn3ak, it only happens when I have more than 13 tags with matching turned on.

[benley]

just adding a backlink to the related nixpkgs issue: NixOS/nixpkgs#240591

(I guess github doesn't automatically cross-reference discussions mentioned from issues? huh.)

[pedrom34]

I'm having the same issue with less powerfull system (SBC, Rock64)
I'm deactivating auto classifier...

[Atemu]

To add a data point: This system of mine is also rather "weak"; a Celeron J4105.

[ryane]

I had it on a VM running on an AMD Ryzen 9 4900H host (with 4 cores and 16 GB allocated to the VM). fwiw, it doesn't seem like it is just hardware. While I'm still on Nixos and same VM, I migrated paperless-ngx to the docker-compose stack and the classifier is running quickly and without any issues (with 35 tags atm).

[Atemu]

Another data point I'd like to investigate is which database we're using. On NixOS, sqlite is the default and likely nobody switches it out because it ought to be enough for paperless purposes. At least that's an easy assumption to make.
I've never installed it through other means than NixOS but at least for the installer script, the default appears to be postgres.

So, which DB are you using and do you experience this issue?

[pedrom34]

I'm using sqlite

[ambroisie]

I use Postgres, and have the same issue reported here by other NixOS users.

[benley]

We seem to have found an effective workaround on NixOS: replacing OpenBLAS with MKL can be done at runtime by setting LD_LIBRARY_PATH (NixOS/nixpkgs#240591 (comment))

[dekimsey]

Just adding a bit context for others, on my FreeBSD 13.2 amd64 system I'm definitely seeing the same behavior getting stuck at the correspondents step and pegging a CPU at 100% for days.

log samples

From paperless.log I have:

[2024-02-23 02:28:28,761] [DEBUG] [paperless.classifier] Gathering data from database...
[2024-02-23 02:28:28,948] [DEBUG] [paperless.classifier] 95 documents, 9 tag(s), 32 correspondent(s), 16 document type(s). 1 storage path(es)
[2024-02-23 02:28:28,948] [DEBUG] [paperless.classifier] Vectorizing data...
[2024-02-23 02:28:34,983] [DEBUG] [paperless.classifier] Training tags classifier...
[2024-02-23 02:28:46,445] [DEBUG] [paperless.classifier] Training correspondent classifier...

And my celery.log has:

[2024-02-20 04:05:00,008] [INFO] [celery.worker.strategy] Task documents.tasks.train_classifier[1e72f305-449f-4883-99e0-cd7ca01cd163] received
OMP: Warning #96: Cannot form a team with 4 threads, using 1 instead.
OMP: Hint Consider unsetting KMP_DEVICE_THREAD_LIMIT (KMP_ALL_THREADS), KMP_TEAMS_THREAD_LIMIT, and OMP_THREAD_LIMIT (if any are set).

Looking at the rest of this thread, I see the FreeBSD math/py-numpy uses math/openblas as well. I confirmed my numpy (1.26.2) is built in a virtualenv (thus not from the port), but it is using the math/openblas package (0.3.20,2). Just for giggles, I did try upgrading the 0.3.25,2 to no avail. For what it's worth, oneMKL is not distributed as source and doesn't seem to be an option for BSD.

The only thing that has addressed this was manually going through and disabling roughly half of the correspondent matching.

And just to share, the classification_model with the 17 correspondents is about 968MB. I know I have some a few rather large documents, but that size just seems a bit much. I don't know much about ML, so shrug.

[Atemu]

Could you try building numpy without openblas support?

[dekimsey]

Could you try building numpy without openblas support?

Oh, that's an idea, I'll give that a try and will let you know!

[pedrom34]

Is there any update on this issue?
The only way I have to keep paperless-ngx running is by deactivating auto-classifier. Is there a way to apply the fix found on nixos on a regular install with docker?

[Atemu]

A (rather poor) workaround is to inject MKL's BLAS implementation.

NixOS/nixpkgs#240591 (comment)

A better workaround would be to disable BLAS in numpy all together like the upstream wheels do. The real fix is likely complicated to find and fix.