Vorbis - Dec 2012 - ov_open_callbacks takes so much time to open 210 MB OGG file

Why ov_open_callbacks(fd_, &vf, NULL, 0, OV_CALLBACKS_NOCLOSE) takes so 
long to open OGG file?
The OGG file has just 210 MB. It takes a lot of time open the file.

I am working on OGG audio recorder and player.

Thanks in advance!

With kind regards,
Pavel

On Wed, Dec 5, 2012 at 5:44 PM, Pavel Nikitenko <pavnsw at gmail.com>
wrote:
> Why ov_open_callbacks(fd_, &vf, NULL, 0, OV_CALLBACKS_NOCLOSE) takes so
> long to open OGG file?
> The OGG file has just 210 MB. It takes a lot of time open the file.
What version of Vorbisfile are you using, and have you verified the
Ogg file itself is correct?

Is it the open process taking time, or is it the codec setup?  What
profiling have you done?  What kind of system is this on?  X86,
embedded...?

Monty

> What version of Vorbisfile are you using, and have you verified the
> Ogg file itself is correct?
The Ogg file is normally playable eg. in VLC media player.
It was created by similar code as it is encoder_example.cpp .
Only difference is that the file is not created at once via audio recording.
But step by step appended to it to the end of file. Every time the audio 
recording is stopped and then after some time started audio record 
again. Similar like concat command does.

I try debug version of the code in Visual Studio 2010 and if I break the 
code, it is in spending time in the

ov_open_callbacks(fd_, &vf, NULL, 0, OV_CALLBACKS_NOCLOSE)

function.

If I use OV_CALLBACKS_STREAMONLY_NOCLOSE instead, it does not take any 
time to open the 210 MB OGG file.

ov_open_callbacks(fd_, &vf, NULL, 0,OV_CALLBACKS_STREAMONLY_NOCLOSE)


If I use smaller OGG file like 2 MB OGG file, it does not take time to 
open the file even with OV_CALLBACKS_NOCLOSE .
I tested 50 MB OGG file, the code also opened it like instantly.
My system is Intel Core2 Duo CPU E6750 2.66GHz with 2 GB of RAM, Windows 
7 64 bit operating system.

Thanks and regards,
Pavel

On 6.12.2012 9:57, xiphmont at xiph.org wrote:
> On Wed, Dec 5, 2012 at 5:44 PM, Pavel Nikitenko <pavnsw at gmail.com>
wrote:
>> Why ov_open_callbacks(fd_, &vf, NULL, 0, OV_CALLBACKS_NOCLOSE)
takes so
>> long to open OGG file?
>> The OGG file has just 210 MB. It takes a lot of time open the file.
> What version of Vorbisfile are you using, and have you verified the
> Ogg file itself is correct?
>
> Is it the open process taking time, or is it the codec setup?  What
> profiling have you done?  What kind of system is this on?  X86,
> embedded...?
>
> Monty

On Thu, Dec 6, 2012 at 4:19 AM, Pavel Nikitenko <pavnsw at gmail.com>
wrote:
> Only difference is that the file is not created at once via audio
recording.
> But step by step appended to it to the end of file. Every time the audio
> recording is stopped and then after some time started audio record
> again. Similar like concat command does.
So its a chained file?

Well? files with a lot of chaining fundamentally take a bit longer to open.

Opusfile has a lot of intelligence for doing this rapidly that vorbisfile lacks,
so there may be an good opportunity for improvement there.

Should I user rather Opusfile or Oggz library?
> Well? files with a lot of chaining fundamentally take a bit longer to open.
Quite long time to open. In minutes. Around 15 minutes.

Any tips?

On 6.12.2012 12:19, Gregory Maxwell wrote:
> On Thu, Dec 6, 2012 at 4:19 AM, Pavel Nikitenko <pavnsw at gmail.com>
wrote:
>> Only difference is that the file is not created at once via audio
recording.
>> But step by step appended to it to the end of file. Every time the
audio
>> recording is stopped and then after some time started audio record
>> again. Similar like concat command does.
> So its a chained file?
>
> Well? files with a lot of chaining fundamentally take a bit longer to open.
>
> Opusfile has a lot of intelligence for doing this rapidly that vorbisfile
lacks,
> so there may be an good opportunity for improvement there.

Thanks for the info. I will try to reproduce the bug with use of: 
libvorbis-1.3.3\examples\vorbisfile_example.c .
> ogginfo complained that streams were not being terminated (no EOS
> page).  That makes the streams invalid, but should not trigger that
> behavior in vorbisfile.  ogginfo also complained about 'garbage
> between pages' at one point, but I've not verified yet that report
is
> correct.  This, also, should not trigger the behavior you're seeing.
I am not sure what that means.
I just try to append new OGG file to existing OGG file. Do you think, 
there is a bug, that the new OGG file is not appended into existing OGG 
file correctly?
At correct position?

Pavel

On 10.12.2012 14:04, xiphmont at xiph.org wrote:
> On Mon, Dec 10, 2012 at 6:22 AM, Pavel Nikitenko <pavnsw at
gmail.com> wrote:
>> Should I user rather Opusfile or Oggz library?
>>
>>
>>> Well? files with a lot of chaining fundamentally take a bit longer
to
>>> open.
>> Quite long time to open. In minutes. Around 15 minutes.
> Goodness gracious.  That's absolutely wrong :-)
>
> I grabbed the file and looked at it; 52 links which is a lot, but not
> 15 minutes a lot. Should be maybe 150ms at worst.  I've not had time
> to look at what is happening beyond a quick run through the various
> inspection tools.
>
> ogginfo complained that streams were not being terminated (no EOS
> page).  That makes the streams invalid, but should not trigger that
> behavior in vorbisfile.  ogginfo also complained about 'garbage
> between pages' at one point, but I've not verified yet that report
is
> correct.  This, also, should not trigger the behavior you're seeing.
>
> So... no news quite yet.  I do plan to have a more detailed look at it.
>
> Monty

Hi Monty and Gregory,

OK. I did some special test.

I use original libvorbis-1.3.3 library vorbisfile_example.c source code 
modified a little the way to be able to measure time which takes 
ov_open_callbacks function. See attached vorbisfile_example.c source code.

And tested it with 210 MB OGG file, which I sent previously.
https://www.dropbox.com/s/rb86nn1yfehp7go/test4.ogg

As you can see it took 1398 seconds ( 23.3 minutes) for the 
ov_open_callbacks function with this file. And it decompressed only 
954880 bytes raw file size, but it finished with done.
(In comparison for just 50 MB OGG file, (maybe with less appending) it 
took 140ms.).

It looks something is wrong. Either something with ov_open_callbacks if 
it is not optimized or the OGG is not generated as it should. I do not 
understand much terminology of the OGG file format. The OGG file is 
generated by appending of new OGG file at the end of previously 
generated OGG file. If there would be better way, I would use it for sure.

Could you please review provided source code and provided OGG file and 
give me some hints so I can move forward some way, please?

Thanks and regards,
Pavel

F:\libvorbis-1.3.3\win32\VS2010\Win32\Release>vorbisfile_static.exe < 
test4.ogg > test4.raw
Starting to measure time of ov_open_callbacks.
clock start:=0
clock end:=1397639
time=1397.639000
ENCODER
Bitstream is 4 channel, 44100Hz

Decoded length: 156133632 samples
Encoded by: Xiph.Org libVorbis I 20120203 (Omnipresent)

Decompressing...Decompressing finished.Done.


On 10.12.2012 14:04, xiphmont at xiph.org wrote:
> On Mon, Dec 10, 2012 at 6:22 AM, Pavel Nikitenko <pavnsw at
gmail.com> wrote:
>> Should I user rather Opusfile or Oggz library?
>>
>>
>>> Well? files with a lot of chaining fundamentally take a bit longer
to
>>> open.
>> Quite long time to open. In minutes. Around 15 minutes.
> Goodness gracious.  That's absolutely wrong :-)
>
> I grabbed the file and looked at it; 52 links which is a lot, but not
> 15 minutes a lot. Should be maybe 150ms at worst.  I've not had time
> to look at what is happening beyond a quick run through the various
> inspection tools.
>
> ogginfo complained that streams were not being terminated (no EOS
> page).  That makes the streams invalid, but should not trigger that
> behavior in vorbisfile.  ogginfo also complained about 'garbage
> between pages' at one point, but I've not verified yet that report
is
> correct.  This, also, should not trigger the behavior you're seeing.
>
> So... no news quite yet.  I do plan to have a more detailed look at it.
>
> Monty
-------------- next part --------------
/********************************************************************
 *                                                                  *
 * THIS FILE IS PART OF THE OggVorbis SOFTWARE CODEC SOURCE CODE.   *
 * USE, DISTRIBUTION AND REPRODUCTION OF THIS LIBRARY SOURCE IS     *
 * GOVERNED BY A BSD-STYLE SOURCE LICENSE INCLUDED WITH THIS SOURCE *
 * IN 'COPYING'. PLEASE READ THESE TERMS BEFORE DISTRIBUTING.       *
 *                                                                  *
 * THE OggVorbis SOURCE CODE IS (C) COPYRIGHT 1994-2007             *
 * by the Xiph.Org Foundation http://www.xiph.org/                  *
 *                                                                  *
 ********************************************************************

 function: simple example decoder using vorbisfile
 last mod: $Id: vorbisfile_example.c 16328 2009-07-24 01:51:10Z xiphmont $

 ********************************************************************/

/* Takes a vorbis bitstream from stdin and writes raw stereo PCM to
   stdout using vorbisfile. Using vorbisfile is much simpler than
   dealing with libvorbis. */

#include <stdio.h>
#include <stdlib.h>
#include <math.h>
#include <vorbis/codec.h>
#include <vorbis/vorbisfile.h>
#include <ctime>

#ifdef _WIN32 /* We need the following two to set stdin/stdout to binary */
#include <io.h>
#include <fcntl.h>
#endif

char pcmout[4096]; /* take 4k out of the data segment, not the stack */

int main(){
  OggVorbis_File vf;
  int eof=0;
  int current_section;

#ifdef _WIN32 /* We need to set stdin/stdout to binary mode. Damn windows. */
  /* Beware the evil ifdef. We avoid these where we can, but this one we 
     cannot. Don't add any more, you'll probably go to hell if you do.
*/
  _setmode( _fileno( stdin ), _O_BINARY );
  _setmode( _fileno( stdout ), _O_BINARY );
#endif

  fprintf(stderr,"Starting to measure time of ov_open_callbacks.");
  clock_t start,end;
  start=clock();
  fprintf(stderr,"\nclock start:=%d\n",start);

  if(ov_open_callbacks(stdin, &vf, NULL, 0, OV_CALLBACKS_NOCLOSE) < 0) {
      fprintf(stderr,"Input does not appear to be an Ogg
bitstream.\n");
      exit(1);
  }

  end=clock();
  fprintf(stderr,"clock end:=%d\n",end);
  fprintf(stderr,"time=%f\n",((double)(end-start))/CLK_TCK);

  /* Throw the comments plus a few lines about the bitstream we're
     decoding */
  {
    char **ptr=ov_comment(&vf,-1)->user_comments;
    vorbis_info *vi=ov_info(&vf,-1);
    while(*ptr){
      fprintf(stderr,"%s\n",*ptr);
      ++ptr;
    }
    fprintf(stderr,"\nBitstream is %d channel,
%ldHz\n",vi->channels,vi->rate);
    fprintf(stderr,"\nDecoded length: %ld samples\n",
            (long)ov_pcm_total(&vf,-1));
    fprintf(stderr,"Encoded by:
%s\n\n",ov_comment(&vf,-1)->vendor);
  }
  
  fprintf(stderr,"Decompressing...");
  while(!eof){
    long ret=ov_read(&vf,pcmout,sizeof(pcmout),0,2,1,&current_section);
    if (ret == 0) {
      /* EOF */
      eof=1;
    } else if (ret < 0) {
      if(ret==OV_EBADLINK){
        fprintf(stderr,"Corrupt bitstream section! Exiting.\n");
        exit(1);
      }

      /* some other error in the stream.  Not a problem, just reporting it in
         case we (the app) cares.  In this case, we don't. */
    } else {
      /* we don't bother dealing with sample rate changes, etc, but
         you'll have to*/
      fwrite(pcmout,1,ret,stdout);
    }
  }
  fprintf(stderr,"Decompressing finished.");

  /* cleanup */
  ov_clear(&vf);
    
  fprintf(stderr,"Done.\n");
  return(0);
}

Hi Monty,

Did you have a chance to look on the observed issue with 
ov_open_callbacks, please?

It takes 23.3 minutes for the ov_open_callbacks function to open my 210 
MB OGG file. But it opens it successfully.
Attached is source code how I measured it.

Should I rather use different library for OGG file playback? If yes, 
which library do you recommend, please?

Thank you very much for any help with the issue and regards,
Pavel
> I did some special test.
>
> I use original libvorbis-1.3.3 library vorbisfile_example.c source 
> code modified a little the way to be able to measure time which takes 
> ov_open_callbacks function. See attached vorbisfile_example.c source 
> code.
>
> And tested it with 210 MB OGG file, which I sent previously.
> https://www.dropbox.com/s/rb86nn1yfehp7go/test4.ogg
>
> As you can see it took 1398 seconds ( 23.3 minutes) for the 
> ov_open_callbacks function with this file. And it decompressed only 
> 954880 bytes raw file size, but it finished with done.
> (In comparison for just 50 MB OGG file, (maybe with less appending) it 
> took 140ms.).
>
> It looks something is wrong. Either something with ov_open_callbacks 
> if it is not optimized or the OGG is not generated as it should. I do 
> not understand much terminology of the OGG file format. The OGG file 
> is generated by appending of new OGG file at the end of previously 
> generated OGG file. If there would be better way, I would use it for 
> sure.
>
> Could you please review provided source code and provided OGG file and 
> give me some hints so I can move forward some way, please?
>
> Thanks and regards,
> Pavel
>
> F:\libvorbis-1.3.3\win32\VS2010\Win32\Release>vorbisfile_static.exe <
> test4.ogg > test4.raw
> Starting to measure time of ov_open_callbacks.
> clock start:=0
> clock end:=1397639
> time=1397.639000
> ENCODER>
> Bitstream is 4 channel, 44100Hz
>
> Decoded length: 156133632 samples
> Encoded by: Xiph.Org libVorbis I 20120203 (Omnipresent)
>
> Decompressing...Decompressing finished.Done. 

On 10.12.2012 14:04, xiphmont at xiph.org wrote:
> On Mon, Dec 10, 2012 at 6:22 AM, Pavel Nikitenko <pavnsw at
gmail.com> wrote:
>> Should I user rather Opusfile or Oggz library?
>>
>>
>>> Well? files with a lot of chaining fundamentally take a bit longer
to
>>> open.
>> Quite long time to open. In minutes. Around 15 minutes.
> Goodness gracious.  That's absolutely wrong :-)
>
> I grabbed the file and looked at it; 52 links which is a lot, but not
> 15 minutes a lot. Should be maybe 150ms at worst.  I've not had time
> to look at what is happening beyond a quick run through the various
> inspection tools.
>
> ogginfo complained that streams were not being terminated (no EOS
> page).  That makes the streams invalid, but should not trigger that
> behavior in vorbisfile.  ogginfo also complained about 'garbage
> between pages' at one point, but I've not verified yet that report
is
> correct.  This, also, should not trigger the behavior you're seeing.
>
> So... no news quite yet.  I do plan to have a more detailed look at it.
>
> Monty
-------------- next part --------------
/********************************************************************
 *                                                                  *
 * THIS FILE IS PART OF THE OggVorbis SOFTWARE CODEC SOURCE CODE.   *
 * USE, DISTRIBUTION AND REPRODUCTION OF THIS LIBRARY SOURCE IS     *
 * GOVERNED BY A BSD-STYLE SOURCE LICENSE INCLUDED WITH THIS SOURCE *
 * IN 'COPYING'. PLEASE READ THESE TERMS BEFORE DISTRIBUTING.       *
 *                                                                  *
 * THE OggVorbis SOURCE CODE IS (C) COPYRIGHT 1994-2007             *
 * by the Xiph.Org Foundation http://www.xiph.org/                  *
 *                                                                  *
 ********************************************************************

 function: simple example decoder using vorbisfile
 last mod: $Id: vorbisfile_example.c 16328 2009-07-24 01:51:10Z xiphmont $

 ********************************************************************/

/* Takes a vorbis bitstream from stdin and writes raw stereo PCM to
   stdout using vorbisfile. Using vorbisfile is much simpler than
   dealing with libvorbis. */

#include <stdio.h>
#include <stdlib.h>
#include <math.h>
#include <vorbis/codec.h>
#include <vorbis/vorbisfile.h>
#include <ctime>

#ifdef _WIN32 /* We need the following two to set stdin/stdout to binary */
#include <io.h>
#include <fcntl.h>
#endif

char pcmout[4096]; /* take 4k out of the data segment, not the stack */

int main(){
  OggVorbis_File vf;
  int eof=0;
  int current_section;

#ifdef _WIN32 /* We need to set stdin/stdout to binary mode. Damn windows. */
  /* Beware the evil ifdef. We avoid these where we can, but this one we 
     cannot. Don't add any more, you'll probably go to hell if you do.
*/
  _setmode( _fileno( stdin ), _O_BINARY );
  _setmode( _fileno( stdout ), _O_BINARY );
#endif

  fprintf(stderr,"Starting to measure time of ov_open_callbacks.");
  clock_t start,end;
  start=clock();
  fprintf(stderr,"\nclock start:=%d\n",start);

  if(ov_open_callbacks(stdin, &vf, NULL, 0, OV_CALLBACKS_NOCLOSE) < 0) {
      fprintf(stderr,"Input does not appear to be an Ogg
bitstream.\n");
      exit(1);
  }

  end=clock();
  fprintf(stderr,"clock end:=%d\n",end);
  fprintf(stderr,"time=%f\n",((double)(end-start))/CLK_TCK);

  /* Throw the comments plus a few lines about the bitstream we're
     decoding */
  {
    char **ptr=ov_comment(&vf,-1)->user_comments;
    vorbis_info *vi=ov_info(&vf,-1);
    while(*ptr){
      fprintf(stderr,"%s\n",*ptr);
      ++ptr;
    }
    fprintf(stderr,"\nBitstream is %d channel,
%ldHz\n",vi->channels,vi->rate);
    fprintf(stderr,"\nDecoded length: %ld samples\n",
            (long)ov_pcm_total(&vf,-1));
    fprintf(stderr,"Encoded by:
%s\n\n",ov_comment(&vf,-1)->vendor);
  }
  
  fprintf(stderr,"Decompressing...");
  while(!eof){
    long ret=ov_read(&vf,pcmout,sizeof(pcmout),0,2,1,&current_section);
    if (ret == 0) {
      /* EOF */
      eof=1;
    } else if (ret < 0) {
      if(ret==OV_EBADLINK){
        fprintf(stderr,"Corrupt bitstream section! Exiting.\n");
        exit(1);
      }

      /* some other error in the stream.  Not a problem, just reporting it in
         case we (the app) cares.  In this case, we don't. */
    } else {
      /* we don't bother dealing with sample rate changes, etc, but
         you'll have to*/
      fwrite(pcmout,1,ret,stdout);
    }
  }
  fprintf(stderr,"Decompressing finished.");

  /* cleanup */
  ov_clear(&vf);
    
  fprintf(stderr,"Done.\n");
  return(0);
}