RE: VuFind Import

[Demian Katz]

I’m copying this message to solrmarc-tech, in case anyone there has additional ideas.

 

A few questions and ideas:

 

1.)    What if you index just one record?  Does it hang after every import, or only against the 27k-record file?

2.)    Do you have the solr.hosturl value set correctly in import/import.properties?  This is used by SolrMarc to send a commit request to Solr over HTTP.  Perhaps this is hanging due to a bad configuration or networking problem; you can try commenting it out to see if that helps, since it is an optional setting.

3.)    How much free memory do you have on your development server?  Is it possible that the Java VM is having trouble managing memory and is getting caught in some sort of horrible garbage collection loop after indexing?  It might be worth experimenting with different JVM memory settings (see the INDEX_OPTIONS variable in import-marc.sh).

 

- Demian

 

From: Nathan Tallman [mailto:ntal...@gmail.com]
Sent: Tuesday, June 19, 2012 11:02 AM
To: Demian Katz
Subject: VuFind Import

 

Hi Demian,

 

On my VuFind development server, something funny is happening. The import script seems to get caught up at the last bib record (Not too many, less than 27K). It stays in that spot for over six hours before it finishes and commits. It will eventually finish, but it just sits on "Jun 19, 2012 10:56:24 AM org.solrmarc.marc.MarcImporter importRecords INFO: Added record 26840 read from file: vtls000026197" for hours.

 

Any ideas why this might be?

 

Thanks,

Nathan

 

[Demian Katz]

One other thing you can try in import.properties as a point of comparison – change solr.path to:

 

solr.path=REMOTE

 

This will cause SolrMarc to update over HTTP instead of writing directly to the index file.  It might be interesting to see if that makes any difference.

 

Another thing that might be interesting to try is running VuFind’s optimize script – just go to VuFind’s util folder while Solr is active and run:

 

php optimize.php

 

Does running that take a very long time?  Does running that prior to indexing make any difference?

 

- Demian

 

From: Nathan Tallman [mailto:ntal...@gmail.com]
Sent: Tuesday, June 19, 2012 12:40 PM
To: Demian Katz
Cc: solrma...@googlegroups.com
Subject: Re: VuFind Import

 

1) I indexed just one record, and it didn't have any hangups... but it did break VuFind: all searches result in HTTP Error 500. Prior to indexing the solo record I turned off VuFind and cleared the solr index, then restarted VuFind. I can access the SOLR admin URL and successfully search for the one record.

 

2) solr.hosturl is correct and commenting it out has no affect.

 

3) There is 8 GB of memory on the server. I adjusting INDEX_OPTIONS to 1024 (from 512) for both settings, but a full-record index still got hung up.

 

Demian, I know you've seen my other messages today to the VuFind LS, could this problem be related to the other problems I am experiencing?

 

Thanks,

Nathan

[Bill Dueber]

Also, look on your server for more than one Solr process listening on that same port. I've had trouble in the past with solr under jetty failing to shut down, hanging onto the port and causing all sorts of weirdness until I figured out what's happening. 

--
You received this message because you are subscribed to the Google Groups "solrmarc-tech" group.
To post to this group, send email to solrma...@googlegroups.com.
To unsubscribe from this group, send email to solrmarc-tec...@googlegroups.com.
For more options, visit this group at http://groups.google.com/group/solrmarc-tech?hl=en.

--
Bill Dueber
Library Systems Programmer
University of Michigan Library

[Simon Spero]

Thoughts: 

1. 27,000 records  doesn't sound like a huge number, so 6hrs sounds like  a long time to be processing a commit  .
2. The importer could be stuck waiting for some kind of lock or timeout; or it could be busy doing I/O, or it could be cpu-bound.  If the solr-core is loaded into the same process, then you can look and see what threads are running and where,  You can use the jvisualvm command to attach to a running java process and see exactly where it's spending its time. 
3. You can use vmstat to look at system activity at a coarse level.  
4. You can use iostat to look at disk activity in more detail
5. You can use strace to look at what system calls the process is  making, or is stuck in
6. You can use jstack to look at the java call stacks for all threads in a given process.

Simon

[Nathan Tallman]

From checking in with top as the process hangs on, it does increase memory and CPU usage as it hangs.

Bill -- Good idea, this has happened to me before too. Unfortunately, it was not the problem.

Simon -- Thank you for your suggestions. Delving into the output of these commands, or at least anything other than a superficial analysis, is beyond me. I've pasted the output for the commands, using the appropriate PID argument where needed. If anything jumps out at you, please let me know.

2. I can't seem to do much with jvisualvm. Centos tells me the command is not found, but I see online that it is supposed to be included with java-1.6.0-openjdk, which is what I'm running (1.6.0_24 actually).

3.

procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----

 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st

 0  0      0 3749988  73396 2195044    0    0    18    34   57   77  1  0 98  0  0

4. 

Linux 2.6.32-220.17.1.el6.x86_64 (localhost.localdomain)        06/19/2012      _x86_64_        (8 CPU)

avg-cpu:  %user   %nice %system %iowait  %steal   %idle

           1.20    0.00    0.11    0.20    0.00   98.49

Device:            tps   Blk_read/s   Blk_wrtn/s   Blk_read   Blk_wrtn

sda               3.81       288.94       549.93    5220270    9935798

dm-0             61.65       109.20       483.63    1973034    8737928

dm-1              0.02         0.17         0.00       3096          0

dm-2              8.95       178.74        65.75    3229314    1188008

5.

Process 27798 attached - interrupt to quit

futex(0x7f85f94949d0, FUTEX_WAIT, 27799, NULL

6.

2012-06-19 14:37:57

Full thread dump OpenJDK 64-Bit Server VM (20.0-b12 mixed mode):

"process reaper" daemon prio=10 tid=0x00007f11958f4000 nid=0x3919 runnable [0x00007f11d8a11000]

   java.lang.Thread.State: RUNNABLE

        at java.lang.UNIXProcess.waitForProcessExit(Native Method)

        at java.lang.UNIXProcess.access$900(UNIXProcess.java:36)

        at java.lang.UNIXProcess$1$1.run(UNIXProcess.java:148)

   Locked ownable synchronizers:

        - None

"Attach Listener" daemon prio=10 tid=0x00007f11a8001000 nid=0x3843 waiting on condition [0x0000000000000000]

   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:

        - None

"pool-2-thread-1" prio=10 tid=0x00007f11ec104800 nid=0xb5e waiting on condition [0x00007f11d87b2000]

   java.lang.Thread.State: WAITING (parking)

        at sun.misc.Unsafe.park(Native Method)

        - parking to wait for  <0x00000000c2bf13b8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)

        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)

        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)

        at java.util.concurrent.DelayQueue.take(DelayQueue.java:189)

        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:688)

        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:681)

        at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1043)

        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1103)

        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)

        at java.lang.Thread.run(Thread.java:679)

   Locked ownable synchronizers:

        - None

"pool-7-thread-1" prio=10 tid=0x00007f119587e800 nid=0xb5d waiting on condition [0x00007f11dbefd000]

   java.lang.Thread.State: WAITING (parking)

        at sun.misc.Unsafe.park(Native Method)

        - parking to wait for  <0x00000000c2beec78> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)

        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)

        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)

        at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:386)

        at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1043)

        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1103)

        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)

        at java.lang.Thread.run(Thread.java:679)

   Locked ownable synchronizers:

        - None

"pool-5-thread-1" prio=10 tid=0x00007f11ec0cb000 nid=0xb5c waiting on condition [0x00007f11dbffe000]

   java.lang.Thread.State: WAITING (parking)

        at sun.misc.Unsafe.park(Native Method)

        - parking to wait for  <0x00000000c2bed978> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)

        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)

at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)

        at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:386)

        at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1043)

        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1103)

        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)

        at java.lang.Thread.run(Thread.java:679)

   Locked ownable synchronizers:

        - None

"pool-5-thread-1" prio=10 tid=0x00007f11ec0cb000 nid=0xb5c waiting on condition [0x00007f11dbffe000]

   java.lang.Thread.State: WAITING (parking)

        at sun.misc.Unsafe.park(Native Method)

        - parking to wait for  <0x00000000c2bed978> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)

        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)

        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)

        at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:386)

        at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1043)

        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1103)

        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)

        at java.lang.Thread.run(Thread.java:679)

   Locked ownable synchronizers:

        - None

"pool-3-thread-1" prio=10 tid=0x00007f11958ea800 nid=0xb5b waiting on condition [0x00007f11e81c6000]

   java.lang.Thread.State: WAITING (parking)

        at sun.misc.Unsafe.park(Native Method)

        - parking to wait for  <0x00000000c2bf9f40> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)

        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)

        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)

        at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:386)

        at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1043)

        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1103)

        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)

        at java.lang.Thread.run(Thread.java:679)

   Locked ownable synchronizers:

        - None

"pool-1-thread-1" prio=10 tid=0x00007f11958bc000 nid=0xb5a waiting on condition [0x00007f11e84cf000]

   java.lang.Thread.State: WAITING (parking)

        at sun.misc.Unsafe.park(Native Method)

        - parking to wait for  <0x00000000c2bedf00> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)

        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)

        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)

        at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:386)

        at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1043)

        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1103)

        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)

        at java.lang.Thread.run(Thread.java:679)

   Locked ownable synchronizers:

        - None

"Low Memory Detector" daemon prio=10 tid=0x00007f11ec0a5000 nid=0xb58 runnable [0x0000000000000000]

   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:

        - None

"C2 CompilerThread1" daemon prio=10 tid=0x00007f11ec0a3000 nid=0xb57 waiting on condition [0x0000000000000000]

   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:

        - None

"C2 CompilerThread0" daemon prio=10 tid=0x00007f11ec0a0000 nid=0xb56 waiting on condition [0x0000000000000000]

   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:

        - None

"Signal Dispatcher" daemon prio=10 tid=0x00007f11ec092000 nid=0xb55 runnable [0x0000000000000000]

   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:

        - None

"Finalizer" daemon prio=10 tid=0x00007f11ec07f800 nid=0xb54 in Object.wait() [0x00007f11e8cfb000]

   java.lang.Thread.State: WAITING (on object monitor)

        at java.lang.Object.wait(Native Method)

        - waiting on <0x00000000c2bf6208> (a java.lang.ref.ReferenceQueue$Lock)

        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:133)

        - locked <0x00000000c2bf6208> (a java.lang.ref.ReferenceQueue$Lock)

        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:149)

        at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:177)

   Locked ownable synchronizers:

        - None

"Reference Handler" daemon prio=10 tid=0x00007f11ec07d800 nid=0xb53 in Object.wait() [0x00007f11e8dfc000]

   java.lang.Thread.State: WAITING (on object monitor)

        at java.lang.Object.wait(Native Method)

       - waiting on <0x00000000c2bf6238> (a java.lang.ref.Reference$Lock)

        at java.lang.Object.wait(Object.java:502)

        at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:133)

        - locked <0x00000000c2bf6238> (a java.lang.ref.Reference$Lock)

   Locked ownable synchronizers:

        - None

"main" prio=10 tid=0x00007f11ec007000 nid=0xb49 runnable [0x00007f11f20cf000]

   java.lang.Thread.State: RUNNABLE

        at java.io.FileInputStream.readBytes(Native Method)

        at java.io.FileInputStream.read(FileInputStream.java:236)

        at java.io.BufferedInputStream.read1(BufferedInputStream.java:273)

        at java.io.BufferedInputStream.read(BufferedInputStream.java:334)

        - locked <0x00000000eb7ce640> (a java.io.BufferedInputStream)

        at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:282)

        at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:324)

        at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:176)

        - locked <0x00000000eb462748> (a java.io.InputStreamReader)

        at java.io.InputStreamReader.read(InputStreamReader.java:184)

        at java.io.BufferedReader.fill(BufferedReader.java:153)

        at java.io.BufferedReader.readLine(BufferedReader.java:316)

        - locked <0x00000000eb462748> (a java.io.InputStreamReader)

        at java.io.BufferedReader.readLine(BufferedReader.java:379)

        at org.solrmarc.index.VuFindIndexer.harvestWithAperture(VuFindIndexer.java:1105)

        at org.solrmarc.index.VuFindIndexer.getFulltext(VuFindIndexer.java:997)

        at org.solrmarc.index.VuFindIndexer.getFulltext(VuFindIndexer.java:1013)

        at sun.reflect.GeneratedMethodAccessor14.invoke(Unknown Source)

        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

        at java.lang.reflect.Method.invoke(Method.java:616)

        at org.solrmarc.index.SolrIndexer.handleCustom(SolrIndexer.java:856)

        at org.solrmarc.index.SolrIndexer.map(SolrIndexer.java:709)

        at org.solrmarc.marc.MarcImporter.addToIndex(MarcImporter.java:382)

        at org.solrmarc.marc.MarcImporter.importRecords(MarcImporter.java:304)

        at org.solrmarc.marc.MarcImporter.handleAll(MarcImporter.java:572)

        at org.solrmarc.marc.MarcImporter.main(MarcImporter.java:832)

        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)

        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

        at java.lang.reflect.Method.invoke(Method.java:616)

        at com.simontuffs.onejar.Boot.run(Boot.java:334)

        at com.simontuffs.onejar.Boot.main(Boot.java:170)

   Locked ownable synchronizers:

        - None

"VM Thread" prio=10 tid=0x00007f11ec076800 nid=0xb52 runnable

"GC task thread#0 (ParallelGC)" prio=10 tid=0x00007f11ec012000 nid=0xb4a runnable

"GC task thread#1 (ParallelGC)" prio=10 tid=0x00007f11ec014000 nid=0xb4b runnable

"GC task thread#2 (ParallelGC)" prio=10 tid=0x00007f11ec016000 nid=0xb4c runnable

"GC task thread#3 (ParallelGC)" prio=10 tid=0x00007f11ec017800 nid=0xb4d runnable

"GC task thread#4 (ParallelGC)" prio=10 tid=0x00007f11ec019800 nid=0xb4e runnable

"GC task thread#5 (ParallelGC)" prio=10 tid=0x00007f11ec01b800 nid=0xb4f runnable

"GC task thread#6 (ParallelGC)" prio=10 tid=0x00007f11ec01d000 nid=0xb50 runnable

"GC task thread#7 (ParallelGC)" prio=10 tid=0x00007f11ec01f000 nid=0xb51 runnable

"VM Periodic Task Thread" prio=10 tid=0x00007f11ec0b0000 nid=0xb59 waiting on condition

JNI global references: 1666

[Simon Spero]

On Tue, Jun 19, 2012 at 2:42 PM, Nathan Tallman <ntal...@gmail.com> wrote:

 

2. I can't seem to do much with jvisualvm. Centos tells me the command is not found, but I see online that it is supposed to be included with java-1.6.0-openjdk, which is what I'm running (1.6.0_24 actually).

I you may need to install the from  "java-1.6.0-openjdk-devel" (I think that's the package name for RHEL). 

The system figures that you showed are probably averages;  if you run them in continuous mode, you get to see the momentary values; however, there may be enough information in the jstack output to narrow things down.

2012-06-19 14:37:57

Full thread dump OpenJDK 64-Bit Server VM (20.0-b12 mixed mode):

[...[

 

"main" prio=10 tid=0x00007f11ec007000 nid=0xb49 runnable [0x00007f11f20cf000]

   java.lang.Thread.State: RUNNABLE

        at java.io.FileInputStream.readBytes(Native Method)

        at java.io.FileInputStream.read(FileInputStream.java:236)

      [InputStream and Reader calls caused by ...] 

        at java.io.BufferedReader.readLine(BufferedReader.java:379)       

       at org.solrmarc.index.VuFindIndexer.harvestWithAperture(VuFindIndexer.java:1105)

        at org.solrmarc.index.VuFindIndexer.getFulltext(VuFindIndexer.java:997)

 

All of the (in)action seems to be taking place on the main thread.  The method that's executing is reading a line from an import stream; the read method is called from VuFindIndexer.harvestWithAperture.

The harvestWithAperture is used to fetch full text, and  operates by running the Aperture web crawler in a separate process.  The read is on the input from the external process;  the external process may well be waiting on a URL.  If you look for a webcrawler.sh process, the URL that is currently being awaited should be on the command line.

 

2012-06-19 14:37:57

Full thread dump OpenJDK 64-Bit Server VM (20.0-b12 mixed mode):

[...[

 

"main" prio=10 tid=0x00007f11ec007000 nid=0xb49 runnable [0x00007f11f20cf000]

   java.lang.Thread.State: RUNNABLE

        at java.io.FileInputStream.readBytes(Native Method)

        at java.io.FileInputStream.read(FileInputStream.java:236)

      [InputStream and Reader calls caused by ...] 

        at java.io.BufferedReader.readLine(BufferedReader.java:379)       

       at org.solrmarc.index.VuFindIndexer.harvestWithAperture(VuFindIndexer.java:1105)

        at org.solrmarc.index.VuFindIndexer.getFulltext(VuFindIndexer.java:997)

Simon

[Nathan Tallman]

Simon that's it! The crawler was getting hung-up on crawling a particular page at the internet archive <http://archive.org/details/karladlercollect01adle>. Not sure what the problem with the page is, but after removing the 856u link everything worked smoothly! It turns out it had a cascading affect, certain records whose IDs are after it were not be being indexed.

Thank you very much for your troubleshooting help!

Nathan

[Demian Katz]

Good to know this is a potential problem area, and glad to hear that fixing just one URL seems to have solved the problem.  If this becomes a recurring problem, let me know and I can look into introducing some kind of timeout value to the full text retrieval.

 

- Demian