180517: disc i/o fails with 40MB/sec voltage sampling.

• clock: 160MHz, output Bw=5MHz, 16 bit voltage sampling polA and polB
• 6 mocks were used (pdevs2 had a degraded disc array).
• data was taken from 12:00 to 15:00
• pdevs2 had a degraded raid array (only 2 discs) so it was not used.
  

    During the run, the mock program aborted with FPGA1 PI fifo error 0x0470 or FPGA1: DMA buffer overflow. The buffer pool monitor data was examined to see what was going on.

The Buffer pool:

• The pnet program:
• Requests  a free shm buffer.
• reads data from the pdev spectrometer into the buffer
• puts the buffer on the bpinp program input queue.
• 
  
• The bpInp program processes the data buffers:
• grab a buffer from its input queue (placed there by pnet
• Processes the buffer.
• For spectral data it does the bit reversal.
• places the processed buffer on the bpOut input queue
• bpOut program loads headers and writes to disc
• grabs buffer from input queue
• loads header info (at least for spectral data)
• outputs the buffer to disc
• puts the buffer back on the shm  free list
  

• Every 5 seconds, it reads the shared memory info holding the queue status.
• It then logs this to disc /data/pdevFiles/bpMon_bnsm.log

The s3279 disc writing errors:

    When voltage sampling is used, the  i/o programs only use the 1st 1Mbyte of each 20Mbyte buffer for recording data. So instead of having 20Mb yte*50bufs = 1Gbyte  of buffer memory, there is only 50*1= 50Mbytes of buffer spaces available. This was initially chosen so there wasn't too long a delay between buffer outputs when slow voltage data sampling was used.
   
    s3279 was taking data  at 40 million bytes /sec (around 38.15  2^20 bytes/sec). 50 1Mbytes byte buffers gave a time slop of only 1.25 seconds.

The plots show the number of free buffers available during the run (.ps)   (.pdf):

• Page 1: number of free buffers vs time for each pdev spectrometer
• Top frame to bottom frame are the different pdev spectrometers (pdevs2 is not included).
• when the buffer count goes to 0, the the i/o will fail.
• The green lines are blown up on page 2.
• Page 2: blowup where i/o failed.
• each + is  a different 5 second sample.
• The red lines show where the buffer count went to zero for a given spectrometer.
• The blue lines are when cima reported that he mocks couldn't keep up with the data rate.
• Cima will force a crash in any of the spectrometers can't keep up.

SUMMARY:

• The i/o could not keep up 3 times during the run (i've excluded the times before pdevs2 was removed).
• In these cases, the free buffer count went to 0.
• looking at the data,  .25 to .5 second backups (10 to 20 buffers) occur regularly.
• I need to look into increasing the packet size used for voltage sampling . I think there was a reason why i didn't want to make it  much larger than 1MByte.

processing: x101/180517/bpmonchk.pro

23feb09: scp data while taking data

02dec08: pdevs1 disk doesn't keep up. (top)

• It had be running for 12384 seconds running at 65mB/sec
• 190*2 2GByte files had been generated for this scan.
• pdevs1 ran out of memory buffers (1 gb or 16 secs of data at 65 mb/sec).
• pdevs2 thru pdevs7 did not slow down. Only pdevs1 failed.

• Timeline:
• 00:25:46 - times the same. last write to file 00287
• 00:25:47 - open file 00288 still in sync
• 00:26:52 - pdevs2 finishes writing file 00288
• 00:26:52 - pdevs2 finishes open,header write file 00289.
  
• 00:26:54 - no scramnet buffers logged to disc for 5 seconds.
  
• 00:26:58/00:27:04 - pdevs1 finishes open to file 00288 and writing headers. 6/12 seconds behind.
• 00:27:08/04 - pdevs1 finished open/header write file 00289.
  
• took 4 seconds from close of previous file.
• is now 16/12 seconds behind pdevs2.
  

• the time in the block
  
• The time when pdevs1 shmScram read the block from the scram multicast
• the time when pdevs1 scrmLog program wrote that block to disc.
  

• The different times are color coded.
• Black is the time stamp in the pntblk.
• Red is when the block was read from the ethernet broadcast
• green is when the block was written to disc
• At 26:54 no scramnet packet was seen for 5 seconds.
• This 2 seconds after pdevs2 close file 288 and 4 seconds before the last write to 00288.s1 on pdevs1.
• The other pdev devices receive the scramnet broadcasts. They did not have any delays in their disc writes.
• The scramnet info is also recorded directly from the shared memory on observer2. During this time period the packets were showing up once a second.
• A delay  in receiving scram net packets could occur if:
• the packets didn't arrive
• the scramShm program could not grab the semaphore for scramShm (bpOut could be holding it).
• An error in writing the scram block out (via scramLog) could cause a delay, but it would also generate a message via syslog and none were seen.
  

summary

• pdevs1 ran out of buffers at 27:10. There are enough buffers for about 16 seconds so the problem could have occured more than 16 seconds prior to this.
  
• pdevs2-pdev7 had no problems.
  
• at 27:04 one of the pdevs1 files was 12 seconds behind the pdevs2 file.
• scramnet buffers stopped being recorded for 5 seconds at 26:54.
• Something slowed down pdevs1 around 26:52.
  
• It  took about 4 seconds to open and write the header files for pdevs1 file 288. Pdevs2 did this within 1 second. These operations don't need any scramnet info so that isn't the reason for the slowdown.
• Looking at pdevs1 raid statistics, disc 5 does not look like it is working 100%.
  
• On 05dec08 we changed disc #5 in the raid array. We'll see if this fixes the problem.
  

Monitoring pdev server cpu & disc with iostat.  (top)

• cpu usage (top plot)
  
• %user (black) . Fraction of time cpu running in user mode.
• %iowait (red). Fraction of time the cpu was not busy and there was an outstanding io request
• %sys (green)  fraction time cpu running in system mode (in the kernel).
• %idle (blue) fraction of time cpu was idle.
• disc i/o rates (middle plot).
• this monitors /dev/sdc1 (/dump/pdev) where the data files are written.
• Write i/o rate (black) in Mbytes/sec
• Read i/o rate (red) in Mbytes/sec
  

Pdev raid disc i/o rates: (top)

• It writes 1000 records of 20Mbytes each to the file /dump/pdev/discwr2.out
• It times each record and the global time (globalStart, write all data, globalStop)
• For the 1000 record times measured it also reports the min,max,mean, and rms of the record times.
• The measurements could vary if someone was using pdevsN or accessing an NFS mounted file.
  

• 16dec09: group 0 now has 5* 1.5TB Drives. It was 6*.75TB drives.
  
• 16may09: arun replaced 750 gb drives on pdevs13 with 1.5 Tb drives.
• first slot in raid no longer working.. 4 drives active.
• i/o rate went from 30mb/sec to 137 mb/sec
  

home_~phil